I already posted this question. I simplified it and hoping (begging) for more response.

I am making a small benchmark to learn more about caching for my graduation thesis.

I did the following (several times):
1) Read 5000 rows from a table -- time = 1019 ms
+ clear session and second level cache
2) Read again the same records -- time = 757 ms

I get much lower time in second case. Why?

It is not because database caching, because I don't get the same behavior with JDBC. Also I don't thing it is because of JIT-compiling because I read some unimportant data before the test, so the code is partly compiled.

If you see the log, it is the same for both cases.

I would be very grateful for your help.

Marko

[code]
------------------------------ CODE --------------------------------------------
SessionFactory sessionFactory;
sessionFactory = new Configuration().configure().buildSessionFactory();

Transaction tx;

final ITimer timer = TimerFactory.newTimer();
Partner partner;

List list;

Session session = sessionFactory.openSession();
tx = session.beginTransaction();
list = session.find("from Material material");
tx.commit();

System.gc();
session.clear();

System.out.println("DEBUG: first reading");
tx = session.beginTransaction();
timer.start();
list = session.find("from Partner partner");
timer.stop();
tx.commit();
out.write("first reading" + "\n");
out.write(timer.getDuration() + "\n");
timer.reset();

session.clear();
sessionFactory.evict(Partner.class);
System.gc();

System.out.println("DEBUG: second reading with empty session and second level cache");
tx = session.beginTransaction();
timer.start();
list = session.find("from Partner partner2");
timer.stop();
tx.commit();
out.write("second reading with empty session and second level cache" + "\n");
out.write(timer.getDuration() + "\n");
timer.reset();

System.gc();

----------------------------- PARTNER.HBM-------------------------------------------

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

<hibernate-mapping>
<class name="si.marko.hibernate.Partner" table="partner" proxy="si.marko.hibernate.Partner">
<cache usage="read-write"/>
<id name="id" column="ID" type="java.lang.Long">
<generator class="native" />
</id>

<property name="naziv" type="string" length="100" not-null="true"/>
<property name="naslov" type="string" length="100"/>
<property name="posta" type="string" length="50"/>
<property name="drzava" type="string" length="50"/>
<property name="davcna" type="string" length="8"/>
<property name="krajZaPlacila" column="kraj_za_placila" type="string" length="10"/>
<property name="transRacSedez" column="trans_rac_sedez" type="string" length="5"/>
<property name="transRac" column="trans_rac" type="string" length="13"/>
<property name="kontOseba" column="kont_oseba" type="string" length="50"/>
<property name="tel" type="string" length="50"/>
<property name="gsm" type="string" length="50"/>
<property name="email" type="string" length="50"/>
<property name="www" type="string" length="100"/>
<property name="opomba" type="string" length="100"/>
</class>
</hibernate-mapping>

------------------- hibernate.cfg.xml ------------------------
<?xml version='1.0' encoding='utf-8'?>
<!DOCTYPE hibernate-configuration PUBLIC
"-//Hibernate/Hibernate Configuration DTD 2.0//EN"

"http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd">

<hibernate-configuration>
<session-factory>
<property name="hibernate.connection.driver_class">
com.newatlanta.jturbo.driver.DataSource
</property>
<property name="hibernate.connection.url">
jdbc:JTurbo://marko:1433/kovinoplastika
</property>
<property name="hibernate.connection.pool_size">4</property>
<property name="hibernate.connection.username">sa</property>
<property name="hibernate.connection.password">marko</property>
<property name="dialect">
net.sf.hibernate.dialect.SQLServerDialect
</property>
<property name="hibernate.cache.use_query_cache">true</property>
<property name="show_sql">false</property>
<property name="transaction.factory_class">
net.sf.hibernate.transaction.JDBCTransactionFactory
</property>

<property name="hibernate.c3p0.max_size">5</property>
<property name="hibernate.c3p0.min_size">5</property>
<property name="hibernate.c3p0.timeout">15000</property>
<property name="hibernate.c3p0.max_statements">100</property>
<property name="hibernate.c3p0.validate">true</property>

<mapping resource="si/marko/hibernate/Partner.hbm" />
</session-factory>
</hibernate-configuration>

------------------ log (just for two records in table) ------------------------

20:47:14,825 INFO Environment:462 - Hibernate 2.1.2
20:47:14,841 INFO Environment:496 - loaded properties from resource hibernate.properties: {hibernate.cglib.use_reflection_optimizer=true, hibernate.cache.provider_class=net.sf.hibernate.cache.HashtableCacheProvider, hibernate.cache.use_query_cache=true, hibernate.max_fetch_depth=1, hibernate.dialect=net.sf.hibernate.dialect.SQLServerDialect, hibernate.jdbc.use_streams_for_binary=true, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', hibernate.jdbc.batch_size=0, hibernate.proxool.pool_alias=pool1, hibernate.connection.username=sa, hibernate.connection.password=marko, hibernate.connection.pool_size=1}
20:47:14,856 INFO Environment:518 - using java.io streams to persist binary types
20:47:14,856 INFO Environment:519 - using CGLIB reflection optimizer
20:47:14,856 INFO Configuration:854 - configuring from resource: /hibernate.cfg.xml
20:47:14,872 INFO Configuration:826 - Configuration resource: /hibernate.cfg.xml
20:47:14,919 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd in classpath under net/sf/hibernate/
20:47:14,919 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd in classpath
20:47:14,966 DEBUG Configuration:812 - hibernate.connection.driver_class=com.newatlanta.jturbo.driver.DataSource
20:47:14,981 DEBUG Configuration:812 - hibernate.connection.url=jdbc:JTurbo://marko:1433/kovinoplastika
20:47:14,981 DEBUG Configuration:812 - hibernate.connection.pool_size=4
20:47:14,981 DEBUG Configuration:812 - hibernate.connection.username=sa
20:47:14,981 DEBUG Configuration:812 - hibernate.connection.password=marko
20:47:14,981 DEBUG Configuration:812 - dialect=net.sf.hibernate.dialect.SQLServerDialect
20:47:14,981 DEBUG Configuration:812 - show_sql=true
20:47:14,981 DEBUG Configuration:812 - transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory
20:47:14,981 DEBUG Configuration:812 - hibernate.c3p0.max_size=5
20:47:14,981 DEBUG Configuration:812 - hibernate.c3p0.min_size=5
20:47:14,981 DEBUG Configuration:812 - hibernate.c3p0.timeout=15000
20:47:14,981 DEBUG Configuration:812 - hibernate.c3p0.max_statements=100
20:47:14,981 DEBUG Configuration:812 - hibernate.c3p0.validate=true
20:47:14,981 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@106082 [Attribute: name resource value "si/marko/hibernate/Kategorija.hbm"]
20:47:14,981 INFO Configuration:311 - Mapping resource: si/marko/hibernate/Kategorija.hbm
20:47:14,981 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:14,997 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,075 INFO Binder:229 - Mapping class: si.marko.hibernate.Kategorija -> kategorija
20:47:15,138 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,153 DEBUG Binder:462 - Mapped property: naziv -> naziv, type: string
20:47:15,153 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@587c94 [Attribute: name resource value "si/marko/hibernate/Artikel.hbm"]
20:47:15,153 INFO Configuration:311 - Mapping resource: si/marko/hibernate/Artikel.hbm
20:47:15,153 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,153 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,184 INFO Binder:229 - Mapping class: si.marko.hibernate.Artikel -> artikel
20:47:15,200 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,200 DEBUG Binder:462 - Mapped property: naziv -> naziv, type: string
20:47:15,200 DEBUG Binder:462 - Mapped property: cena -> cena, type: big_decimal
20:47:15,200 DEBUG Binder:462 - Mapped property: enota -> enota, type: string
20:47:15,200 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,200 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@14c1103 [Attribute: name resource value "si/marko/hibernate/Inventura.hbm"]
20:47:15,200 INFO Configuration:311 - Mapping resource: si/marko/hibernate/Inventura.hbm
20:47:15,200 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,200 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,216 INFO Binder:229 - Mapping class: si.marko.hibernate.Inventura -> inventura
20:47:15,216 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,216 DEBUG Binder:462 - Mapped property: datum -> datum, type: date
20:47:15,216 DEBUG Binder:462 - Mapped property: kolicina -> kolicina, type: double
20:47:15,216 DEBUG Binder:462 - Mapped property: cena -> cena, type: big_decimal
20:47:15,216 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,231 DEBUG Binder:462 - Mapped property: material -> materialID, type: si.marko.hibernate.Material
20:47:15,231 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@1fc2fb [Attribute: name resource value "si/marko/hibernate/Material.hbm"]
20:47:15,231 INFO Configuration:311 - Mapping resource: si/marko/hibernate/Material.hbm
20:47:15,231 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,231 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,247 INFO Binder:229 - Mapping class: si.marko.hibernate.Material -> material
20:47:15,247 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,247 DEBUG Binder:462 - Mapped property: naziv -> naziv, type: string
20:47:15,247 DEBUG Binder:462 - Mapped property: enota -> enota, type: string
20:47:15,247 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,247 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@77a7f9 [Attribute: name resource value "si/marko/hibernate/Normativ.hbm"]
20:47:15,247 INFO Configuration:311 - Mapping resource: si/marko/hibernate/Normativ.hbm
20:47:15,263 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,263 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,278 INFO Binder:229 - Mapping class: si.marko.hibernate.Normativ -> normativ
20:47:15,278 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,278 DEBUG Binder:462 - Mapped property: normativ -> normativ, type: double
20:47:15,278 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,278 DEBUG Binder:462 - Mapped property: artikel -> artikelID, type: si.marko.hibernate.Artikel
20:47:15,294 DEBUG Binder:462 - Mapped property: material -> materialID, type: si.marko.hibernate.Material
20:47:15,294 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@1f6f296 [Attribute: name resource value "si/marko/hibernate/IzdaniRacun.hbm"]
20:47:15,294 INFO Configuration:311 - Mapping resource: si/marko/hibernate/IzdaniRacun.hbm
20:47:15,294 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,294 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,309 INFO Binder:229 - Mapping class: si.marko.hibernate.IzdaniRacun -> izdani_racun
20:47:15,309 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,309 DEBUG Binder:462 - Mapped property: stRacuna -> st_racuna, type: string
20:47:15,309 DEBUG Binder:462 - Mapped property: stDobavnice -> st_dobavnice, type: string
20:47:15,309 DEBUG Binder:462 - Mapped property: stNarocilnice -> st_narocilnice, type: string
20:47:15,309 DEBUG Binder:462 - Mapped property: datum -> datum, type: date
20:47:15,309 DEBUG Binder:462 - Mapped property: datumOprStor -> datum_opr_stor, type: date
20:47:15,309 DEBUG Binder:462 - Mapped property: datumZapad -> datum_zapad, type: date
20:47:15,309 DEBUG Binder:462 - Mapped property: partner -> partnerID, type: si.marko.hibernate.Partner
20:47:15,309 DEBUG Binder:462 - Mapped property: avansniRacun -> avansni_rac, type: string
20:47:15,325 DEBUG Binder:462 - Mapped property: narocil -> narocil, type: string
20:47:15,325 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,325 DEBUG Binder:462 - Mapped property: postavke, type: java.util.Set
20:47:15,325 INFO Binder:547 - Mapping collection: si.marko.hibernate.IzdaniRacun.kategorija -> izdani_racun_kategorija
20:47:15,325 DEBUG Binder:462 - Mapped property: kategorija, type: java.util.Set
20:47:15,325 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@544ec1 [Attribute: name resource value "si/marko/hibernate/PostavkaIzdRac.hbm"]
20:47:15,325 INFO Configuration:311 - Mapping resource: si/marko/hibernate/PostavkaIzdRac.hbm
20:47:15,341 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,341 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,356 INFO Binder:229 - Mapping class: si.marko.hibernate.PostavkaIzdRac -> postavka_izd_rac
20:47:15,356 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,356 DEBUG Binder:462 - Mapped property: davek -> davek, type: double
20:47:15,356 DEBUG Binder:462 - Mapped property: kolicina -> kolicina, type: double
20:47:15,356 DEBUG Binder:462 - Mapped property: cenaBrezDDV -> cena_brez_DDV, type: big_decimal
20:47:15,356 DEBUG Binder:462 - Mapped property: rabat -> rabat, type: double
20:47:15,356 DEBUG Binder:462 - Mapped property: racun -> izd_racID, type: si.marko.hibernate.IzdaniRacun
20:47:15,388 INFO Binder:169 - Mapping subclass: si.marko.hibernate.PostavkaIzdRacObic -> postavka_izd_rac
20:47:15,403 DEBUG Binder:462 - Mapped property: postavka -> postavka, type: string
20:47:15,403 INFO Binder:169 - Mapping subclass: si.marko.hibernate.PostavkaIzdRacArt -> postavka_izd_rac
20:47:15,403 DEBUG Binder:462 - Mapped property: artikel -> artikelID, type: si.marko.hibernate.Artikel
20:47:15,403 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@4fce71 [Attribute: name resource value "si/marko/hibernate/PrejetiRacun.hbm"]
20:47:15,403 INFO Configuration:311 - Mapping resource: si/marko/hibernate/PrejetiRacun.hbm
20:47:15,403 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,403 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,419 INFO Binder:229 - Mapping class: si.marko.hibernate.PrejetiRacun -> prejeti_racun
20:47:15,419 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,419 DEBUG Binder:462 - Mapped property: stRacuna -> st_racuna, type: string
20:47:15,419 DEBUG Binder:462 - Mapped property: stDobavnice -> st_dobavnice, type: string
20:47:15,419 DEBUG Binder:462 - Mapped property: partner -> partnerID, type: si.marko.hibernate.Partner
20:47:15,419 DEBUG Binder:462 - Mapped property: datum -> datum, type: date
20:47:15,419 DEBUG Binder:462 - Mapped property: datumOdpreme -> datum_odpreme, type: date
20:47:15,419 DEBUG Binder:462 - Mapped property: datumZapadlosti -> datum_zapadlosti, type: date
20:47:15,419 DEBUG Binder:462 - Mapped property: modelSklica -> model_sklica, type: string
20:47:15,419 DEBUG Binder:462 - Mapped property: sklic -> sklic, type: string
20:47:15,419 DEBUG Binder:462 - Mapped property: namen -> namen, type: string
20:47:15,434 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,434 DEBUG Binder:462 - Mapped property: znesek -> znesek, type: big_decimal
20:47:15,434 DEBUG Binder:462 - Mapped property: davek -> davek, type: big_decimal
20:47:15,434 DEBUG Binder:462 - Mapped property: postavke, type: java.util.Set
20:47:15,434 INFO Binder:547 - Mapping collection: si.marko.hibernate.PrejetiRacun.kategorija -> prejeti_racun_kategorija
20:47:15,434 DEBUG Binder:462 - Mapped property: kategorija, type: java.util.Set
20:47:15,434 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@79717e [Attribute: name resource value "si/marko/hibernate/PostavkaPrejRac.hbm"]
20:47:15,434 INFO Configuration:311 - Mapping resource: si/marko/hibernate/PostavkaPrejRac.hbm
20:47:15,434 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,434 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,450 INFO Binder:229 - Mapping class: si.marko.hibernate.PostavkaPrejRac -> postavka_prej_rac
20:47:15,450 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,450 DEBUG Binder:462 - Mapped property: davek -> davek, type: double
20:47:15,450 DEBUG Binder:462 - Mapped property: kolicina -> kolicina, type: double
20:47:15,450 DEBUG Binder:462 - Mapped property: cenaNaEnotoBrezDDV -> cena_na_enoto_brez_DDV, type: big_decimal
20:47:15,450 DEBUG Binder:462 - Mapped property: rabat -> rabat, type: double
20:47:15,450 DEBUG Binder:462 - Mapped property: racun -> prej_racID, type: si.marko.hibernate.PrejetiRacun
20:47:15,450 DEBUG Binder:462 - Mapped property: material -> materialID, type: si.marko.hibernate.Material
20:47:15,450 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@12a3722 [Attribute: name resource value "si/marko/hibernate/NormativIzdRac.hbm"]
20:47:15,450 INFO Configuration:311 - Mapping resource: si/marko/hibernate/NormativIzdRac.hbm
20:47:15,450 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,450 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,466 INFO Binder:229 - Mapping class: si.marko.hibernate.NormativIzdRac -> normativ_izd__rac
20:47:15,466 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,466 DEBUG Binder:462 - Mapped property: normativ -> normativ, type: string
20:47:15,466 DEBUG Binder:462 - Mapped property: postavkaIzdRac -> postavkaID, type: si.marko.hibernate.PostavkaIzdRac
20:47:15,466 DEBUG Binder:462 - Mapped property: material -> materialID, type: si.marko.hibernate.Material
20:47:15,466 DEBUG Configuration:971 - null<-org.dom4j.tree.DefaultAttribute@62937c [Attribute: name resource value "si/marko/hibernate/Partner.hbm"]
20:47:15,466 INFO Configuration:311 - Mapping resource: si/marko/hibernate/Partner.hbm
20:47:15,466 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
20:47:15,481 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
20:47:15,481 INFO Binder:229 - Mapping class: si.marko.hibernate.Partner -> partner
20:47:15,481 DEBUG Binder:462 - Mapped property: id -> ID, type: long
20:47:15,481 DEBUG Binder:462 - Mapped property: naziv -> naziv, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: naslov -> naslov, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: posta -> posta, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: drzava -> drzava, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: davcna -> davcna, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: krajZaPlacila -> kraj_za_placila, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: transRacSedez -> trans_rac_sedez, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: transRac -> trans_rac, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: kontOseba -> kont_oseba, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: tel -> tel, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: gsm -> gsm, type: string
20:47:15,481 DEBUG Binder:462 - Mapped property: email -> email, type: string
20:47:15,497 DEBUG Binder:462 - Mapped property: www -> www, type: string
20:47:15,497 DEBUG Binder:462 - Mapped property: opomba -> opomba, type: string
20:47:15,497 INFO Configuration:1017 - Configured SessionFactory: null
20:47:15,497 DEBUG Configuration:1018 - properties: {java.vendor=Sun Microsystems Inc., show_sql=true, hibernate.connection.url=jdbc:JTurbo://marko:1433/kovinoplastika, os.name=Windows XP, sun.boot.class.path=C:\Program Files\Java\j2re1.4.2_03\lib\rt.jar;C:\Program Files\Java\j2re1.4.2_03\lib\i18n.jar;C:\Program Files\Java\j2re1.4.2_03\lib\sunrsasign.jar;C:\Program Files\Java\j2re1.4.2_03\lib\jsse.jar;C:\Program Files\Java\j2re1.4.2_03\lib\jce.jar;C:\Program Files\Java\j2re1.4.2_03\lib\charsets.jar;C:\Program Files\Java\j2re1.4.2_03\classes, hibernate.c3p0.max_size=5, sun.java2d.fontpath=, java.vm.specification.vendor=Sun Microsystems Inc., java.runtime.version=1.4.2_03-b02, hibernate.c3p0.min_size=5, hibernate.cache.provider_class=net.sf.hibernate.cache.HashtableCacheProvider, user.name=Marko, hibernate.c3p0.timeout=15000, user.language=sl, sun.boot.library.path=C:\Program Files\Java\j2re1.4.2_03\bin, dialect=net.sf.hibernate.dialect.SQLServerDialect, java.version=1.4.2_03, user.timezone=Europe/Prague, sun.arch.data.model=32, java.endorsed.dirs=C:\Program Files\Java\j2re1.4.2_03\lib\endorsed, sun.cpu.isalist=pentium i486 i386, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.cglib.use_reflection_optimizer=true, java.class.version=48.0, user.country=SI, java.home=C:\Program Files\Java\j2re1.4.2_03, java.vm.info=mixed mode, hibernate.c3p0.validate=true, os.version=5.1, transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory, path.separator=;, java.vm.version=1.4.2_03-b02, hibernate.max_fetch_depth=1, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, hibernate.connection.password=marko, user.variant=, hibernate.jdbc.batch_size=0, java.awt.printerjob=sun.awt.windows.WPrinterJob, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=sa, user.home=C:\Documents and Settings\Marko, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', java.specification.vendor=Sun Microsystems Inc., java.library.path=C:\Program Files\Java\j2re1.4.2_03\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;c:\Program Files\Microsoft SQL Server\80\Tools\Binn\;c:\java\jdk\bin\;c:\ant\bin\;c:\hib\lib, java.vendor.url=http://java.sun.com/, hibernate.connection.driver_class=com.newatlanta.jturbo.driver.DataSource, hibernate.proxool.pool_alias=pool1, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=net.sf.hibernate.dialect.SQLServerDialect, hibernate.jdbc.use_streams_for_binary=true, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=C:\hib\bin;C:\hib\lib\cglib-2.0-rc2.jar;C:\hib\lib\commons-collections-2.1.jar;C:\hib\lib\commons-logging-1.0.3.jar;C:\hib\lib\dom4j-1.4.jar;C:\hib\lib\hibernate2.jar;C:\hib\lib\jdbc2_0-stdext.jar;C:\hib\lib\jta.jar;C:\hib\lib\jtds-0.7.1.jar;C:\hib\lib\JTurbo.jar;C:\hib\lib\log4j-1.2.8.jar;C:\hib\lib\odmg-3.0.jar;C:\hib\lib\hrtlib.jar;C:\hib\lib\c3p0-0.8.3.jar;C:\hib\lib\ehcache-0.6.jar;C:\hib\lib\msbase.jar;C:\hib\lib\mssqlserver.jar;C:\hib\lib\msutil.jar;C:\hib\lib\JSQLConnect.jar, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, sun.cpu.endian=little, sun.os.patch.level=, hibernate.cache.use_query_cache=true, java.io.tmpdir=C:\DOCUME~1\Marko\LOCALS~1\Temp\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, os.arch=x86, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=C:\Program Files\Java\j2re1.4.2_03\lib\ext, user.dir=C:\hib, line.separator=
, java.vm.name=Java HotSpot(TM) Client VM, file.encoding=Cp1250, java.specification.version=1.4, hibernate.c3p0.max_statements=100, hibernate.show_sql=true, hibernate.connection.pool_size=4}
20:47:15,497 INFO Configuration:595 - processing one-to-many association mappings
20:47:15,497 DEBUG Binder:1326 - Second pass for collection: si.marko.hibernate.IzdaniRacun.postavke
20:47:15,497 INFO Binder:1154 - Mapping collection: si.marko.hibernate.IzdaniRacun.postavke -> postavka_izd_rac
20:47:15,497 DEBUG Binder:1341 - Mapped collection key: izd_racID, one-to-many: si.marko.hibernate.PostavkaIzdRac
20:47:15,497 DEBUG Binder:1326 - Second pass for collection: si.marko.hibernate.IzdaniRacun.kategorija
20:47:15,513 DEBUG Binder:1341 - Mapped collection key: izd_racID, element: kategorijaID, type: si.marko.hibernate.Kategorija
20:47:15,513 DEBUG Binder:1326 - Second pass for collection: si.marko.hibernate.PrejetiRacun.postavke
20:47:15,513 INFO Binder:1154 - Mapping collection: si.marko.hibernate.PrejetiRacun.postavke -> postavka_prej_rac
20:47:15,513 DEBUG Binder:1341 - Mapped collection key: prej_racID, one-to-many: si.marko.hibernate.PostavkaPrejRac
20:47:15,513 DEBUG Binder:1326 - Second pass for collection: si.marko.hibernate.PrejetiRacun.kategorija
20:47:15,513 DEBUG Binder:1341 - Mapped collection key: prejetiRacunID, element: kategorijaID, type: si.marko.hibernate.Kategorija
20:47:15,513 INFO Configuration:604 - processing one-to-one association property references
20:47:15,513 INFO Configuration:629 - processing foreign key constraints
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.PrejetiRacun
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Material
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Artikel
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.IzdaniRacun
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Partner
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Kategorija
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.IzdaniRacun
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Artikel
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Material
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.PrejetiRacun
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Kategorija
20:47:15,513 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Material
20:47:15,528 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.PostavkaIzdRac
20:47:15,528 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Material
20:47:15,528 DEBUG Configuration:639 - resolving reference to class: si.marko.hibernate.Partner
20:47:15,544 INFO Dialect:82 - Using dialect: net.sf.hibernate.dialect.SQLServerDialect
20:47:15,544 INFO SettingsFactory:58 - Maximim outer join fetch depth: 1
20:47:15,544 INFO SettingsFactory:62 - Use outer join fetching: true
20:47:15,544 INFO C3P0ConnectionProvider:48 - C3P0 using driver: com.newatlanta.jturbo.driver.DataSource at URL: jdbc:JTurbo://marko:1433/kovinoplastika
20:47:15,544 INFO C3P0ConnectionProvider:49 - Connection properties: {user=sa, password=marko}
20:47:15,622 INFO TransactionFactoryFactory:31 - Transaction strategy: net.sf.hibernate.transaction.JDBCTransactionFactory
20:47:15,622 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
20:47:16,028 INFO SettingsFactory:102 - Use scrollable result sets: true
20:47:16,028 INFO SettingsFactory:105 - Use JDBC3 getGeneratedKeys(): false
20:47:16,028 INFO SettingsFactory:108 - Optimize cache for minimal puts: false
20:47:16,028 INFO SettingsFactory:114 - echoing all SQL to stdout
20:47:16,028 INFO SettingsFactory:117 - Query language substitutions: {no='N', true=1, yes='Y', false=0}
20:47:16,028 INFO SettingsFactory:128 - cache provider: net.sf.hibernate.cache.HashtableCacheProvider
20:47:16,028 INFO Configuration:1080 - instantiating and configuring caches
20:47:16,138 INFO SessionFactoryImpl:119 - building session factory
20:47:16,138 DEBUG SessionFactoryImpl:125 - instantiating session factory with properties: {java.vendor=Sun Microsystems Inc., show_sql=true, hibernate.connection.url=jdbc:JTurbo://marko:1433/kovinoplastika, os.name=Windows XP, sun.boot.class.path=C:\Program Files\Java\j2re1.4.2_03\lib\rt.jar;C:\Program Files\Java\j2re1.4.2_03\lib\i18n.jar;C:\Program Files\Java\j2re1.4.2_03\lib\sunrsasign.jar;C:\Program Files\Java\j2re1.4.2_03\lib\jsse.jar;C:\Program Files\Java\j2re1.4.2_03\lib\jce.jar;C:\Program Files\Java\j2re1.4.2_03\lib\charsets.jar;C:\Program Files\Java\j2re1.4.2_03\classes, hibernate.c3p0.max_size=5, sun.java2d.fontpath=, java.vm.specification.vendor=Sun Microsystems Inc., java.runtime.version=1.4.2_03-b02, hibernate.c3p0.min_size=5, hibernate.cache.provider_class=net.sf.hibernate.cache.HashtableCacheProvider, user.name=Marko, hibernate.c3p0.timeout=15000, user.language=sl, sun.boot.library.path=C:\Program Files\Java\j2re1.4.2_03\bin, dialect=net.sf.hibernate.dialect.SQLServerDialect, java.version=1.4.2_03, user.timezone=Europe/Prague, sun.arch.data.model=32, java.endorsed.dirs=C:\Program Files\Java\j2re1.4.2_03\lib\endorsed, sun.cpu.isalist=pentium i486 i386, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.cglib.use_reflection_optimizer=true, java.class.version=48.0, user.country=SI, java.home=C:\Program Files\Java\j2re1.4.2_03, java.vm.info=mixed mode, hibernate.c3p0.validate=true, os.version=5.1, transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory, path.separator=;, java.vm.version=1.4.2_03-b02, hibernate.max_fetch_depth=1, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, hibernate.connection.password=marko, user.variant=, hibernate.jdbc.batch_size=0, java.awt.printerjob=sun.awt.windows.WPrinterJob, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=sa, user.home=C:\Documents and Settings\Marko, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', java.specification.vendor=Sun Microsystems Inc., java.library.path=C:\Program Files\Java\j2re1.4.2_03\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;c:\Program Files\Microsoft SQL Server\80\Tools\Binn\;c:\java\jdk\bin\;c:\ant\bin\;c:\hib\lib, java.vendor.url=http://java.sun.com/, hibernate.connection.driver_class=com.newatlanta.jturbo.driver.DataSource, hibernate.proxool.pool_alias=pool1, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=net.sf.hibernate.dialect.SQLServerDialect, hibernate.jdbc.use_streams_for_binary=true, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=C:\hib\bin;C:\hib\lib\cglib-2.0-rc2.jar;C:\hib\lib\commons-collections-2.1.jar;C:\hib\lib\commons-logging-1.0.3.jar;C:\hib\lib\dom4j-1.4.jar;C:\hib\lib\hibernate2.jar;C:\hib\lib\jdbc2_0-stdext.jar;C:\hib\lib\jta.jar;C:\hib\lib\jtds-0.7.1.jar;C:\hib\lib\JTurbo.jar;C:\hib\lib\log4j-1.2.8.jar;C:\hib\lib\odmg-3.0.jar;C:\hib\lib\hrtlib.jar;C:\hib\lib\c3p0-0.8.3.jar;C:\hib\lib\ehcache-0.6.jar;C:\hib\lib\msbase.jar;C:\hib\lib\mssqlserver.jar;C:\hib\lib\msutil.jar;C:\hib\lib\JSQLConnect.jar, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, sun.cpu.endian=little, sun.os.patch.level=, hibernate.cache.use_query_cache=true, java.io.tmpdir=C:\DOCUME~1\Marko\LOCALS~1\Temp\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, os.arch=x86, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=C:\Program Files\Java\j2re1.4.2_03\lib\ext, user.dir=C:\hib, line.separator=
, java.vm.name=Java HotSpot(TM) Client VM, file.encoding=Cp1250, java.specification.version=1.4, hibernate.c3p0.max_statements=100, hibernate.show_sql=true, hibernate.connection.pool_size=4}
20:47:16,731 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
20:47:16,731 DEBUG SessionFactoryObjectFactory:76 - registered: 40288024fc99705b00fc99705dfb0000 (unnamed)
20:47:16,731 INFO SessionFactoryObjectFactory:82 - no JNDI name configured
20:47:16,731 DEBUG SessionFactoryImpl:196 - instantiated session factory
20:47:16,747 INFO UpdateTimestampsCache:35 - starting update timestamps cache at region: net.sf.hibernate.cache.UpdateTimestampsCache
20:47:16,747 INFO QueryCache:39 - starting query cache at region: net.sf.hibernate.cache.QueryCache
20:47:16,809 DEBUG SessionImpl:531 - opened session
20:47:16,809 DEBUG JDBCTransaction:37 - begin
20:47:16,825 DEBUG JDBCTransaction:41 - current autocommit status:false
20:47:16,825 DEBUG SessionImpl:1497 - find: from Material material
20:47:16,841 DEBUG QueryTranslator:147 - compiling query
20:47:16,856 DEBUG SessionImpl:2210 - flushing session
20:47:16,856 DEBUG SessionImpl:2403 - Flushing entities and processing referenced collections
20:47:16,856 DEBUG SessionImpl:2746 - Processing unreferenced collections
20:47:16,856 DEBUG SessionImpl:2760 - Scheduling collection removes/(re)creates/updates
20:47:16,856 DEBUG SessionImpl:2234 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
20:47:16,856 DEBUG SessionImpl:2239 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
20:47:16,856 DEBUG SessionImpl:1782 - Dont need to execute flush
20:47:16,856 DEBUG QueryTranslator:199 - HQL: from si.marko.hibernate.Material material
20:47:16,856 DEBUG QueryTranslator:200 - SQL: select material0_.ID as ID, material0_.naziv as naziv, material0_.enota as enota, material0_.opomba as opomba from material material0_
20:47:16,856 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
20:47:16,856 DEBUG SQL:237 - select material0_.ID as ID, material0_.naziv as naziv, material0_.enota as enota, material0_.opomba as opomba from material material0_
Hibernate: select material0_.ID as ID, material0_.naziv as naziv, material0_.enota as enota, material0_.opomba as opomba from material material0_
20:47:16,856 DEBUG BatcherImpl:241 - preparing statement
20:47:16,888 DEBUG Loader:197 - processing result set
20:47:16,888 DEBUG LongType:68 - returning '1' as column: ID
20:47:16,903 DEBUG Loader:405 - result row: 1
20:47:16,903 DEBUG Loader:536 - Initializing object from ResultSet: 1
20:47:16,903 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#1
20:47:16,903 DEBUG StringType:68 - returning 'granulat' as column: naziv
20:47:16,903 DEBUG StringType:68 - returning 'kg' as column: enota
20:47:16,903 DEBUG StringType:64 - returning null as column: opomba
20:47:16,903 DEBUG LongType:68 - returning '2' as column: ID
20:47:16,903 DEBUG Loader:405 - result row: 2
20:47:16,903 DEBUG Loader:536 - Initializing object from ResultSet: 2
20:47:16,903 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#2
20:47:16,903 DEBUG StringType:68 - returning 'kartoni' as column: naziv
20:47:16,903 DEBUG StringType:68 - returning 'kom' as column: enota
20:47:16,903 DEBUG StringType:64 - returning null as column: opomba
20:47:16,903 DEBUG LongType:68 - returning '4' as column: ID
20:47:16,903 DEBUG Loader:405 - result row: 4
20:47:16,919 DEBUG Loader:536 - Initializing object from ResultSet: 4
20:47:16,919 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#4
20:47:16,919 DEBUG StringType:68 - returning 'os za rolle-Westermaier fi 6/1' as column: naziv
20:47:16,919 DEBUG StringType:68 - returning 'kom' as column: enota
20:47:16,919 DEBUG StringType:64 - returning null as column: opomba
20:47:16,919 DEBUG LongType:68 - returning '5' as column: ID
20:47:16,919 DEBUG Loader:405 - result row: 5
20:47:16,919 DEBUG Loader:536 - Initializing object from ResultSet: 5
20:47:16,919 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#5
20:47:16,919 DEBUG StringType:68 - returning 'os za rolle-Westermaier fi 8/2' as column: naziv
20:47:16,919 DEBUG StringType:68 - returning 'kom' as column: enota
20:47:16,919 DEBUG StringType:64 - returning null as column: opomba
20:47:16,919 DEBUG LongType:68 - returning '6' as column: ID
20:47:16,919 DEBUG Loader:405 - result row: 6
20:47:16,919 DEBUG Loader:536 - Initializing object from ResultSet: 6
20:47:16,919 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#6
20:47:16,919 DEBUG StringType:68 - returning 'granulat - VELE' as column: naziv
20:47:16,919 DEBUG StringType:68 - returning 'kg' as column: enota
20:47:16,919 DEBUG StringType:64 - returning null as column: opomba
20:47:16,919 DEBUG LongType:68 - returning '7' as column: ID
20:47:16,919 DEBUG Loader:405 - result row: 7
20:47:16,919 DEBUG Loader:536 - Initializing object from ResultSet: 7
20:47:16,919 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#7
20:47:16,919 DEBUG StringType:68 - returning 'kartoni - VELE' as column: naziv
20:47:16,934 DEBUG StringType:68 - returning 'kom' as column: enota
20:47:16,934 DEBUG StringType:64 - returning null as column: opomba
20:47:16,934 DEBUG LongType:68 - returning '9' as column: ID
20:47:16,934 DEBUG Loader:405 - result row: 9
20:47:16,934 DEBUG Loader:536 - Initializing object from ResultSet: 9
20:47:16,934 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#9
20:47:16,934 DEBUG StringType:68 - returning 'tampotisk' as column: naziv
20:47:16,934 DEBUG StringType:68 - returning 'kom' as column: enota
20:47:16,934 DEBUG StringType:64 - returning null as column: opomba
20:47:16,934 DEBUG LongType:68 - returning '10' as column: ID
20:47:16,934 DEBUG Loader:405 - result row: 10
20:47:16,934 DEBUG Loader:536 - Initializing object from ResultSet: 10
20:47:16,934 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Material#10
20:47:16,934 DEBUG StringType:68 - returning 'os za rolle-Westermaier fi 8/3' as column: naziv
20:47:16,934 DEBUG StringType:64 - returning null as column: enota
20:47:16,934 DEBUG StringType:64 - returning null as column: opomba
20:47:16,934 DEBUG Loader:226 - done processing result set (8 rows)
20:47:16,934 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
20:47:16,934 DEBUG BatcherImpl:261 - closing statement
20:47:16,934 DEBUG Loader:239 - total objects hydrated: 8
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#1]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#1]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#2]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#2]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#4]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#4]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#5]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#5]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#6]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#6]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#7]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#7]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#9]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#9]
20:47:16,950 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Material#10]
20:47:16,950 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Material#10]
20:47:16,950 DEBUG SessionImpl:3082 - initializing non-lazy collections
20:47:16,950 DEBUG JDBCTransaction:59 - commit
20:47:16,950 DEBUG SessionImpl:2210 - flushing session
20:47:16,950 DEBUG SessionImpl:2403 - Flushing entities and processing referenced collections
20:47:16,950 DEBUG SessionImpl:2746 - Processing unreferenced collections
20:47:16,950 DEBUG SessionImpl:2760 - Scheduling collection removes/(re)creates/updates
20:47:16,966 DEBUG SessionImpl:2234 - Flushed: 0 insertions, 0 updates, 0 deletions to 8 objects
20:47:16,966 DEBUG SessionImpl:2239 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
20:47:16,966 DEBUG Printer:75 - listing entities:
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=kartoni - VELE, opomba=null, enota=kom, id=7}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=tampotisk, opomba=null, enota=kom, id=9}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=granulat - VELE, opomba=null, enota=kg, id=6}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=granulat, opomba=null, enota=kg, id=1}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=os za rolle-Westermaier fi 6/1, opomba=null, enota=kom, id=4}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=kartoni, opomba=null, enota=kom, id=2}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=os za rolle-Westermaier fi 8/3, opomba=null, enota=null, id=10}
20:47:16,966 DEBUG Printer:82 - si.marko.hibernate.Material{naziv=os za rolle-Westermaier fi 8/2, opomba=null, enota=kom, id=5}
20:47:16,966 DEBUG SessionImpl:2323 - executing flush
20:47:16,966 DEBUG SessionImpl:2790 - post flush
20:47:16,966 DEBUG SessionImpl:561 - transaction completion
DEBUG: first reading
20:47:17,028 DEBUG JDBCTransaction:37 - begin
20:47:17,028 DEBUG JDBCTransaction:41 - current autocommit status:false
20:47:17,044 DEBUG SessionImpl:1497 - find: from Partner partner
20:47:17,044 DEBUG QueryTranslator:147 - compiling query
20:47:17,044 DEBUG SessionImpl:2210 - flushing session
20:47:17,044 DEBUG SessionImpl:2403 - Flushing entities and processing referenced collections
20:47:17,044 DEBUG SessionImpl:2746 - Processing unreferenced collections
20:47:17,044 DEBUG SessionImpl:2760 - Scheduling collection removes/(re)creates/updates
20:47:17,044 DEBUG SessionImpl:2234 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
20:47:17,044 DEBUG SessionImpl:2239 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
20:47:17,044 DEBUG SessionImpl:1782 - Dont need to execute flush
20:47:17,044 DEBUG QueryTranslator:199 - HQL: from si.marko.hibernate.Partner partner
20:47:17,044 DEBUG QueryTranslator:200 - SQL: select partner0_.ID as ID, partner0_.naziv as naziv, partner0_.naslov as naslov, partner0_.posta as posta, partner0_.drzava as drzava, partner0_.davcna as davcna, partner0_.kraj_za_placila as kraj_za_7_, partner0_.trans_rac_sedez as trans_ra8_, partner0_.trans_rac as trans_rac, partner0_.kont_oseba as kont_oseba, partner0_.tel as tel, partner0_.gsm as gsm, partner0_.email as email, partner0_.www as www, partner0_.opomba as opomba from partner partner0_
20:47:17,044 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
20:47:17,044 DEBUG SQL:237 - select partner0_.ID as ID, partner0_.naziv as naziv, partner0_.naslov as naslov, partner0_.posta as posta, partner0_.drzava as drzava, partner0_.davcna as davcna, partner0_.kraj_za_placila as kraj_za_7_, partner0_.trans_rac_sedez as trans_ra8_, partner0_.trans_rac as trans_rac, partner0_.kont_oseba as kont_oseba, partner0_.tel as tel, partner0_.gsm as gsm, partner0_.email as email, partner0_.www as www, partner0_.opomba as opomba from partner partner0_
Hibernate: select partner0_.ID as ID, partner0_.naziv as naziv, partner0_.naslov as naslov, partner0_.posta as posta, partner0_.drzava as drzava, partner0_.davcna as davcna, partner0_.kraj_za_placila as kraj_za_7_, partner0_.trans_rac_sedez as trans_ra8_, partner0_.trans_rac as trans_rac, partner0_.kont_oseba as kont_oseba, partner0_.tel as tel, partner0_.gsm as gsm, partner0_.email as email, partner0_.www as www, partner0_.opomba as opomba from partner partner0_
20:47:17,044 DEBUG BatcherImpl:241 - preparing statement
20:47:17,044 DEBUG Loader:197 - processing result set
20:47:17,044 DEBUG LongType:68 - returning '1' as column: ID
20:47:17,044 DEBUG Loader:405 - result row: 1
20:47:17,044 DEBUG Loader:536 - Initializing object from ResultSet: 1
20:47:17,044 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Partner#1
20:47:17,044 DEBUG StringType:68 - returning 'Testno podjetje d.o.o' as column: naziv
20:47:17,044 DEBUG StringType:68 - returning 'Ljubljanska 13' as column: naslov
20:47:17,044 DEBUG StringType:68 - returning '1000 Ljubljana' as column: posta
20:47:17,044 DEBUG StringType:68 - returning 'Slovenija' as column: drzava
20:47:17,059 DEBUG StringType:68 - returning '12345678' as column: davcna
20:47:17,059 DEBUG StringType:68 - returning 'LJUBLJANA' as column: kraj_za_7_
20:47:17,059 DEBUG StringType:68 - returning '10100' as column: trans_ra8_
20:47:17,059 DEBUG StringType:68 - returning '1111111111' as column: trans_rac
20:47:17,059 DEBUG StringType:68 - returning 'Franci' as column: kont_oseba
20:47:17,059 DEBUG StringType:68 - returning '01/111-11-11' as column: tel
20:47:17,059 DEBUG StringType:68 - returning '031/333-333' as column: gsm
20:47:17,059 DEBUG StringType:68 - returning 'test@podjetje.si' as column: email
20:47:17,059 DEBUG StringType:68 - returning 'www.podjetje.si' as column: www
20:47:17,059 DEBUG StringType:68 - returning 'Testno podjetje' as column: opomba
20:47:17,059 DEBUG LongType:68 - returning '2' as column: ID
20:47:17,059 DEBUG Loader:405 - result row: 2
20:47:17,059 DEBUG Loader:536 - Initializing object from ResultSet: 2
20:47:17,059 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Partner#2
20:47:17,059 DEBUG StringType:68 - returning 'Testno podjetje d.o.o' as column: naziv
20:47:17,059 DEBUG StringType:68 - returning 'Ljubljanska 13' as column: naslov
20:47:17,059 DEBUG StringType:68 - returning '1000 Ljubljana' as column: posta
20:47:17,059 DEBUG StringType:68 - returning 'Slovenija' as column: drzava
20:47:17,059 DEBUG StringType:68 - returning '12345678' as column: davcna
20:47:17,059 DEBUG StringType:68 - returning 'LJUBLJANA' as column: kraj_za_7_
20:47:17,059 DEBUG StringType:68 - returning '10100' as column: trans_ra8_
20:47:17,059 DEBUG StringType:68 - returning '1111111111' as column: trans_rac
20:47:17,075 DEBUG StringType:68 - returning 'Franci' as column: kont_oseba
20:47:17,075 DEBUG StringType:68 - returning '01/111-11-11' as column: tel
20:47:17,075 DEBUG StringType:68 - returning '031/333-333' as column: gsm
20:47:17,075 DEBUG StringType:68 - returning 'test@podjetje.si' as column: email
20:47:17,075 DEBUG StringType:68 - returning 'www.podjetje.si' as column: www
20:47:17,075 DEBUG StringType:68 - returning 'Testno podjetje' as column: opomba
20:47:17,075 DEBUG Loader:226 - done processing result set (2 rows)
20:47:17,075 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
20:47:17,075 DEBUG BatcherImpl:261 - closing statement
20:47:17,075 DEBUG Loader:239 - total objects hydrated: 2
20:47:17,075 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Partner#1]
20:47:17,075 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Partner#1]
20:47:17,075 DEBUG SessionImpl:2166 - resolving associations for [si.marko.hibernate.Partner#2]
20:47:17,075 DEBUG SessionImpl:2190 - done materializing entity [si.marko.hibernate.Partner#2]
20:47:17,075 DEBUG SessionImpl:3082 - initializing non-lazy collections
20:47:17,075 DEBUG JDBCTransaction:59 - commit
20:47:17,075 DEBUG SessionImpl:2210 - flushing session
20:47:17,075 DEBUG SessionImpl:2403 - Flushing entities and processing referenced collections
20:47:17,075 DEBUG SessionImpl:2746 - Processing unreferenced collections
20:47:17,075 DEBUG SessionImpl:2760 - Scheduling collection removes/(re)creates/updates
20:47:17,075 DEBUG SessionImpl:2234 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
20:47:17,075 DEBUG SessionImpl:2239 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
20:47:17,075 DEBUG Printer:75 - listing entities:
20:47:17,075 DEBUG Printer:82 - si.marko.hibernate.Partner{www=www.podjetje.si, krajZaPlacila=LJUBLJANA, davcna=12345678, drzava=Slovenija, kontOseba=Franci, opomba=Testno podjetje, id=1, naslov=Ljubljanska 13, gsm=031/333-333, naziv=Testno podjetje d.o.o, email=test@podjetje.si, posta=1000 Ljubljana, transRacSedez=10100, tel=01/111-11-11, transRac=1111111111}
20:47:17,075 DEBUG Printer:82 - si.marko.hibernate.Partner{www=www.podjetje.si, krajZaPlacila=LJUBLJANA, davcna=12345678, drzava=Slovenija, kontOseba=Franci, opomba=Testno podjetje, id=2, naslov=Ljubljanska 13, gsm=031/333-333, naziv=Testno podjetje d.o.o, email=test@podjetje.si, posta=1000 Ljubljana, transRacSedez=10100, tel=01/111-11-11, transRac=1111111111}
20:47:17,075 DEBUG SessionImpl:2323 - executing flush
20:47:17,075 DEBUG SessionImpl:2790 - post flush
20:47:17,075 DEBUG SessionImpl:561 - transaction completion
DEBUG: second reading with empty session and second level cache
20:47:17,153 DEBUG JDBCTransaction:37 - begin
20:47:17,153 DEBUG JDBCTransaction:41 - current autocommit status:false
20:47:17,153 DEBUG SessionImpl:1497 - find: from Partner partner2
20:47:17,153 DEBUG QueryTranslator:147 - compiling query
20:47:17,153 DEBUG SessionImpl:2210 - flushing session
20:47:17,153 DEBUG SessionImpl:2403 - Flushing entities and processing referenced collections
20:47:17,153 DEBUG SessionImpl:2746 - Processing unreferenced collections
20:47:17,153 DEBUG SessionImpl:2760 - Scheduling collection removes/(re)creates/updates
20:47:17,153 DEBUG SessionImpl:2234 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
20:47:17,153 DEBUG SessionImpl:2239 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
20:47:17,153 DEBUG SessionImpl:1782 - Dont need to execute flush
20:47:17,153 DEBUG QueryTranslator:199 - HQL: from si.marko.hibernate.Partner partner2
20:47:17,153 DEBUG QueryTranslator:200 - SQL: select partner0_.ID as ID, partner0_.naziv as naziv, partner0_.naslov as naslov, partner0_.posta as posta, partner0_.drzava as drzava, partner0_.davcna as davcna, partner0_.kraj_za_placila as kraj_za_7_, partner0_.trans_rac_sedez as trans_ra8_, partner0_.trans_rac as trans_rac, partner0_.kont_oseba as kont_oseba, partner0_.tel as tel, partner0_.gsm as gsm, partner0_.email as email, partner0_.www as www, partner0_.opomba as opomba from partner partner0_
20:47:17,153 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
20:47:17,153 DEBUG SQL:237 - select partner0_.ID as ID, partner0_.naziv as naziv, partner0_.naslov as naslov, partner0_.posta as posta, partner0_.drzava as drzava, partner0_.davcna as davcna, partner0_.kraj_za_placila as kraj_za_7_, partner0_.trans_rac_sedez as trans_ra8_, partner0_.trans_rac as trans_rac, partner0_.kont_oseba as kont_oseba, partner0_.tel as tel, partner0_.gsm as gsm, partner0_.email as email, partner0_.www as www, partner0_.opomba as opomba from partner partner0_
Hibernate: select partner0_.ID as ID, partner0_.naziv as naziv, partner0_.naslov as naslov, partner0_.posta as posta, partner0_.drzava as drzava, partner0_.davcna as davcna, partner0_.kraj_za_placila as kraj_za_7_, partner0_.trans_rac_sedez as trans_ra8_, partner0_.trans_rac as trans_rac, partner0_.kont_oseba as kont_oseba, partner0_.tel as tel, partner0_.gsm as gsm, partner0_.email as email, partner0_.www as www, partner0_.opomba as opomba from partner partner0_
20:47:17,153 DEBUG BatcherImpl:241 - preparing statement
20:47:17,169 DEBUG Loader:197 - processing result set
20:47:17,169 DEBUG LongType:68 - returning '1' as column: ID
20:47:17,169 DEBUG Loader:405 - result row: 1
20:47:17,169 DEBUG Loader:536 - Initializing object from ResultSet: 1
20:47:17,169 DEBUG Loader:605 - Hydrating entity: si.marko.hibernate.Partner#1
20:47:17,169 DEBUG StringType:68 - returning 'Testno podjetje d.o.o' as column: naziv
20:47:17,169 DEBUG StringType:68 - returning 'Ljubljanska 13' as column: naslov
20:47:17,169 DEBUG StringType:68 - returning '1000 Ljubljana' as column: posta
20:47:17,169 DEBUG StringType:68 - returning 'Slovenija' as column: drzava
20:47:17,169 DEBUG StringType:68 - returning '12345678' as column: davcna
20:47:17,169 DEBUG StringType:68 - returning 'LJUBLJANA' as column: kraj_za_7_
20:47:17,169 DEBUG StringType:68 - returning '10100' as column: trans_ra8_
20:47:17,169 DEBUG StringType:68 - returning '1111111111' as column: trans_rac
20:47:17,169 DEBUG Str

Error in mapping - actual mapping is without
<cache usage="read-write"/>

Did you use PreparedStatements or Statements in your JDBC code? Hibernate uses PreparedStatements.

i'd suggest putting the code in a loop and running it 100 times outputing the time it took. Something like...



You'll probably find the time starts off about 2-3 times what it will settle down to after 3/4 runs.

I'm almost certain it will be db and JITing that causes the second run to go faster. Also some JDBC drivers cache prepared statements in various ways so subsequent runs of the same query will benefit.

Move the timer calls round the find() only if you prefer but for a decent size table the session/transaction overhead will be negligible.

No, I used Statement. Good hind. Thanks a lot.

I tested now with PreparedStatement, but there is no difference - probably because (as to my knowledge) MS SQL Server doesn't use precompiled statements (at least there is so with stored procedures).

Second JDBC call with Statement or PreparedStatement about 10% faster, but with Hibernate is 25%. I tested with ADO and ADO.NET and there is almost no difference in second call.

I am really grateful for your help.

Marko

I tested it and it was quite surprising. If I run it in a loop it falls for 22% the second time, for 40% the third time and it stays around there. The most suppressing for me it is that it also falls the third time, and for so much. Can it really be JIT? I also read some dummy data before test and it should reduce JIT.

1176
922 22%
700 40%
590 50%
744 37%
600 49%
693 41%
710 40%
597 49%

THANKS A LOT!

Marko

My knowledge of exactly how JIT/Hotspot works is limited but I would say in the first run you have the following overhead..

1) DB hitting the disk to retrieve the results ( will be cached )
2) JIT processing code for the first time ( your code, hibernate and driver )
3) JDBC driver doing internal caching ( maybe )
4) Internal hibernate caches ( maybe )

second run 1), 2) and 4) will surely have been eliminated. But now new code will likely be being called to do cache lookups which is another load of JITing to do on the second run.

1) JIT of cache lookup code in hibernate and driver

Finally third run all the lookup code is JITed, your query and possibly its results will be have been cached at the db, driver and hibernate level in various forms so you should hit your best performance around the third run.

Try removing the dummy lookup on material and i'd expect to see similar results. And then try a lookup on partner instead of the dummy material lookup and you should see the first loop iteration running much faster than before. You can force the db to physically hit the disk by starting and stopping the db engine to clear its caches.

All in all I wouldn't worry about it, once the VM has crunched through the code in the real world a couple of times things settle out nicely.

There are really a lot of reasons for such behavior. I was sure I was doing something wrong, but if I count all reasons you mentioned together they could easily reach 25% lower time in second reading.

Thank you a lot for your generous help. I wish I could pay you back.

Best regards,

Marko