Random long pauses with tiny database

catchpole · **Posted:** Wed Oct 05, 2005 9:04 pm

Hey dudes,

We here at Queensland Emergency Services are generally "fix it ourselves" kinds of people (as we are: "break it ourselves").. But while we search high and low for an answer, we thought we would run this very stange problem past the Hibernate world...

This is approximately the 10th record that was loaded in this request. Note the six second pause halfway through loading this record. CPU seems to be busy during the pause. It seems to be fairly random as to when it pauses, but it does consistently pause on every request.

The personnel class has 5 many-to-one relationships, all of which have lazy="false" and outer-join="true" set on them. It also has 3 many-to-many sets, all of which have lazy="true" set on them.

We dont' have caching turned, at least not that I'm aware of. The method that does the retrieval is as follows.

Code:

    public Collection getAllPersonnel() throws HibernateException {
        Criteria criteria = session.createCriteria(Personnel.class);
        criteria.addOrder(Order.asc("surname"));
        criteria.addOrder(Order.asc("firstName"));        
        return criteria.list();
    }

This is called from a JSF backing bean via a business delegate and a stateless session EJB. All of this is running on weblogic 9.0 using the oracle thin XA driver. Hibernate version is 3.0.

There are currently only 14 unique results in the database, and the entire request takes about 19 seconds.

Code:

25:25,296 DEBUG Loader:828 - result row: null, null, null, EntityKey[au.gov.qld.emergency.fims.persistence.AddressDetail#1], EntityKey[au.gov.qld.emergency.fims.persistence.PersonalTitle#73], EntityKey[au.gov.qld.emergency.fims.persistence.Personnel#200]
25:25,296 DEBUG Loader:978 - Initializing object from ResultSet: [au.gov.qld.emergency.fims.persistence.Personnel#200]
25:25,296 DEBUG BasicEntityPersister:1651 - Hydrating entity: [au.gov.qld.emergency.fims.persistence.Personnel#200]
25:25,296 DEBUG StringType:86 - returning 'Angus' as column: FIRST2_44_5_
25:25,296 DEBUG StringType:80 - returning null as column: MIDDLE3_44_5_
25:25,296 DEBUG StringType:86 - returning 'Smith' as column: SURNAME44_5_
25:25,296 DEBUG StringType:86 - returning 'Bull' as column: PREFERRED5_44_5_
25:25,312 DEBUG TimestampType:86 - returning '1979-08-08 00:00:00' as column: DATE6_44_5_
25:25,312 DEBUG BooleanType:86 - returning 'false' as column: DATE7_44_5_
25:25,312 DEBUG StringType:86 - returning 'M' as column: GENDER44_5_
25:25,312 DEBUG StringType:80 - returning null as column: NOTES44_5_
25:25,312 DEBUG BooleanType:86 - returning 'false' as column: NOTES10_44_5_
25:25,312 DEBUG StringType:80 - returning null as column: PICTURE11_44_5_
25:25,312 DEBUG TimestampType:80 - returning null as column: DECEASED12_44_5_
25:25,312 DEBUG StringType:80 - returning null as column: PREFERRED13_44_5_
25:31,578 DEBUG StringType:80 - returning null as column: ABN44_5_
25:31,593 DEBUG BooleanType:86 - returning 'false' as column: PICTURE15_44_5_
25:31,593 DEBUG BooleanType:86 - returning 'false' as column: HOME16_44_5_
25:31,593 DEBUG BooleanType:86 - returning 'false' as column: POSTAL17_44_5_
25:31,593 DEBUG BooleanType:86 - returning 'false' as column: BUSINESS18_44_5_
25:31,593 DEBUG StringType:80 - returning null as column: SURNAME19_44_5_
25:31,593 DEBUG BooleanType:86 - returning 'false' as column: ABN20_44_5_
25:31,609 DEBUG LongType:86 - returning '0' as column: VERSION44_5_
25:31,609 DEBUG LongType:80 - returning null as column: DRIVERS22_44_5_
25:31,609 DEBUG LongType:80 - returning null as column: BUSINESS23_44_5_
25:31,609 DEBUG LongType:80 - returning null as column: POSTAL24_44_5_
25:31,609 DEBUG LongType:86 - returning '1' as column: HOME25_44_5_
25:31,609 DEBUG IntegerType:86 - returning '73' as column: PERSONAL26_44_5_
25:31,609 DEBUG LongType:80 - returning null as column: DRIVERS1_7_
25:31,625 DEBUG Loader:410 - result set row: 9
25:31,625 DEBUG LongType:80 - returning null as column: ID0_
25:31,625 DEBUG LongType:80 - returning null as column: ID1_
25:31,625 DEBUG LongType:80 - returning null as column: ID2_
25:31,625 DEBUG LongType:86 - returning '1' as column: ID3_
25:31,625 DEBUG IntegerType:86 - returning '77' as column: ATTRIBUTE1_4_
25:31,625 DEBUG LongType:86 - returning '210' as column: ID5_

here's another example...

Code:

31:02,859 DEBUG Loader:828 - result row: EntityKey[au.gov.qld.emergency.fims.persistence.DriversLicence#4], null, null, EntityKey[au.gov.qld.emergency.fims.persistence.AddressDetail#1], EntityKey[au.gov.qld.emergency.fims.persistence.PersonalTitle#75], EntityKey[au.gov.qld.emergency.fims.persistence.Personnel#230]
31:02,859 DEBUG Loader:978 - Initializing object from ResultSet: [au.gov.qld.emergency.fims.persistence.DriversLicence#4]
31:02,859 DEBUG BasicEntityPersister:1651 - Hydrating entity: [au.gov.qld.emergency.fims.persistence.DriversLicence#4]
31:02,859 DEBUG StringType:86 - returning '00000' as column: LICENSE2_15_0_
31:02,859 DEBUG StringType:86 - returning 'QLD' as column: LICENCE3_15_0_
31:02,859 DEBUG TimestampType:86 - returning '2006-06-12 00:00:00' as column: EXPIRY4_15_0_
31:02,859 DEBUG IntegerType:86 - returning '0' as column: SILENT5_15_0_
31:02,859 DEBUG IntegerType:86 - returning '0' as column: VERSION15_0_
31:02,875 DEBUG Loader:978 - Initializing object from ResultSet: [au.gov.qld.emergency.fims.persistence.PersonalTitle#75]
31:02,875 DEBUG BasicEntityPersister:1651 - Hydrating entity: [au.gov.qld.emergency.fims.persistence.PersonalTitle#75]
31:02,875 DEBUG StringType:86 - returning 'Miss' as column: VALUE4_4_
31:02,906 DEBUG StringType:86 - returning 'Miss' as column: DESCRIPT4_4_4_
31:09,328 DEBUG TimestampType:86 - returning '2005-09-21 00:00:00' as column: EFFECTIVE5_4_4_
31:09,328 DEBUG TimestampType:80 - returning null as column: EFFECTIVE6_4_4_
31:09,328 DEBUG LongType:80 - returning null as column: INITIATED7_4_4_
31:09,328 DEBUG IntegerType:86 - returning '0' as column: VERSION4_4_
31:09,328 DEBUG StringType:86 - returning 'PERSONAL_TITLE' as column: ATTRIBUTE2_4_4_
31:09,328 DEBUG Loader:978 - Initializing object from ResultSet: [au.gov.qld.emergency.fims.persistence.Personnel#230]
31:09,343 DEBUG BasicEntityPersister:1651 - Hydrating entity: [au.gov.qld.emergency.fims.persistence.Personnel#230]
31:09,359 DEBUG StringType:86 - returning 'Aishwarya' as column: FIRST2_44_5_
31:09,359 DEBUG StringType:80 - returning null as column: MIDDLE3_44_5_
31:09,359 DEBUG StringType:86 - returning 'Rai' as column: SURNAME44_5_
31:09,359 DEBUG StringType:86 - returning 'Ash' as column: PREFERRED5_44_5_
31:09,359 DEBUG TimestampType:86 - returning '1972-04-04 00:00:00' as column: DATE6_44_5_
31:09,359 DEBUG BooleanType:86 - returning 'true' as column: DATE7_44_5_
31:09,359 DEBUG StringType:86 - returning 'F' as column: GENDER44_5_
31:09,375 DEBUG StringType:80 - returning null as column: NOTES44_5_
31:09,375 DEBUG BooleanType:86 - returning 'false' as column: NOTES10_44_5_
31:09,375 DEBUG StringType:80 - returning null as column: PICTURE11_44_5_
31:09,375 DEBUG TimestampType:80 - returning null as column: DECEASED12_44_5_
31:09,375 DEBUG StringType:80 - returning null as column: PREFERRED13_44_5_
31:09,375 DEBUG StringType:80 - returning null as column: ABN44_5_
31:09,375 DEBUG BooleanType:86 - returning 'false' as column: PICTURE15_44_5_
31:09,375 DEBUG BooleanType:86 - returning 'true' as column: HOME16_44_5_
31:09,375 DEBUG BooleanType:86 - returning 'false' as column: POSTAL17_44_5_
31:09,390 DEBUG BooleanType:86 - returning 'true' as column: BUSINESS18_44_5_
31:09,390 DEBUG StringType:80 - returning null as column: SURNAME19_44_5_
31:09,390 DEBUG BooleanType:86 - returning 'false' as column: ABN20_44_5_
31:09,390 DEBUG LongType:86 - returning '0' as column: VERSION44_5_
31:09,390 DEBUG LongType:86 - returning '4' as column: DRIVERS22_44_5_
31:09,390 DEBUG LongType:80 - returning null as column: BUSINESS23_44_5_
31:09,390 DEBUG LongType:80 - returning null as column: POSTAL24_44_5_
31:09,406 DEBUG LongType:86 - returning '1' as column: HOME25_44_5_
31:09,406 DEBUG IntegerType:86 - returning '75' as column: PERSONAL26_44_5_
31:09,406 DEBUG LongType:86 - returning '4' as column: DRIVERS1_7_

catchpole · **Posted:** Wed Oct 05, 2005 10:42 pm

Hmmm... Works blindingly fast on another developer's machine.. The issue probably has nothing to do with hibernate...

Code:

    surf's up..

     o
    /|\
    _))__
   @####@
  @###   @
  @##

baliukas · **Posted:** Thu Oct 06, 2005 3:28 am

try to tune JVM using parameters like "-Xmx", it sounds like a problem with garbage collection.