Hibernate version:2.1.2

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

<hibernate-mapping package="trex.restricted.model.beans">
<class
name="ReconciliationDtl"
table="RECONCILIATION_DTL"
>

<id name="trackingNbr" type="java.lang.String">
<column name="TRACKING_NBR" not-null="true" unique="true" />
<generator class="assigned" />
</id>

<property
name="cusip"
column="CUSIP"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="12"
/>

<property
name="reconciledSource"
column="RECONCILED_SOURCE"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="10"
/>

<property
name="reconciledInd"
column="RECONCILED_IND"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="1"
/>
<property
name="asOfDate"
column="AS_OF_DATE"
type="date"
insert="true"
update="true"
not-null="false"
length="10"
/>

<property
name="transId"
column="TRANS_ID"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="16"
/>

<property
name="checkNumber"
column="CHECK_NUMBER"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="9"
/>
<property
name="settlDate"
column="SETTL_DATE"
type="date"
insert="true"
update="true"
not-null="false"
length="10"
/>
<property
name="age"
column="AGE"
type="integer"
insert="true"
update="true"
not-null="false"
length="10"
/>

<property
name="sourceDtl"
column="SOURCE_DTL"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="1"
/>
<!--type="big_decimal"-->
<property
name="shares"
column="SHARES"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="18"
/>
<!--type="big_decimal"-->
<property
name="price"
column="PRICE"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="10"
/>

<property
name="reconciledNbr"
column="RECONCILED_NBR"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="18"
/>

<property
name="comments"
column="COMMENTS"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="250"
/>

<property
name="userId"
column="USER_ID"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="8"
/>
<!--type="big_decimal"-->
<property
name="reconciledAmtDif"
column="RECONCILED_AMT_DIF"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="18"
/>
<!--type="timestamp"-->
<property
name="updateDate"
column="UPDATE_DATE"
type="java.lang.String"
insert="true"
update="true"
not-null="false"
length="26"
/>
<property
name="cancelDate"
column="CANCEL_DATE"
type="date"
insert="true"
update="false"
not-null="false"
length="10"
/>

<property
name="plan"
column="PLAN"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="3"
/>

<property
name="pendingInd"
column="PENDING_IND"
type="java.lang.String"
insert="true"
update="false"
not-null="false"
length="1"
/>

<property
name="dbCrInd"
column="DB_CR_IND"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="1"
/>
<!--type="big_decimal"-->
<property
name="amount"
column="AMOUNT"
type="java.lang.String"
insert="true"
update="true"
not-null="true"
length="18"
/>
<!--type="timestamp"-->
<property
name="processDate"
column="PROCESS_DATE"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="26"
/>

<property
name="socSecNbr"
column="SOC_SEC_NBR"
type="java.lang.String"
insert="true"
update="false"
not-null="false"
length="9"
/>
<property
name="tradeDate"
column="TRADE_DATE"
type="date"
insert="true"
update="true"
not-null="false"
length="10"
/>
<property
name="transDate"
column="TRANS_DATE"
type="date"
insert="true"
update="false"
not-null="false"
length="10"
/>

<property
name="option"
column="OPTION"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="3"
/>

<property
name="productId"
column="PRODUCT_ID"
type="java.lang.String"
insert="true"
update="false"
not-null="true"
length="2"
/>

<many-to-one
name="sp"
class="SecurityPlan"
cascade="none"
update="false"
insert="false"
column="CUSIP"
/>
</class>
</hibernate-mapping>




Code between sessionFactory.openSession() and session.close():
try {
session = (Application.getInstance()).getDbSessionRestricted();
String sql = generateQuery(prod, type);
_logger.debug("Generate HQL query for the Product : " + prod + ", Settl date : " + latestSettlDt + ", Report type : " + type);
_logger.debug(sql);
Query q=session.createQuery(sql);
if (type.equals("exception")){
age = 1;
q.setInteger("Age", age);
}
q.setString("ProductId", prod);
if (prod.equals("RS")){
q.setString("endSettlDate", latestSettlDt);
}
_logger.debug("Before executing query");
myReport = q.list();
_logger.debug("record(s): " + myReport.size());
}
catch (HibernateException e)
{
String err = "HibernateException occurred when getting report data";
_logger.fatal(err, e);
HibernateException he = new HibernateException(err);
throw he;
}
catch (Exception e)
{
String err = "Unable to get report data";
_logger.fatal(err, e);
throw e;
}
finally {
if (session.isOpen())
session.close();
}


Full stack trace of any exception that occurs:

Name and version of the database you are using: mainframe DB2 v 7

The generated SQL (show_sql=true):

select recondispl2_.PLAN_LBL as x0_0_, reconcilia0_.PLAN as x1_0_, reconcilia0_.CUSIP as x2_0_, securitypl1_.PLAN_NAME as x3_0_, reconcilia0_.TRADE_DATE as x4_0_, reconcilia0_.SOURCE_DTL as x5_0_, reconcilia0_.TRANS_ID as x6_0_, count(reconcilia0_.TRANS_ID) as x7_0_, sum(reconcilia0_.SHARES) as x8_0_ from VMFDB2P.RECONCILIATION_DTL reconcilia0_ left outer join VMFDB2P.SECURITY_PLAN securitypl1_ on reconcilia0_.CUSIP=securitypl1_.CUSIP, VMFDB2P.RECON_DISPLAY recondispl2_ where (reconcilia0_.PRODUCT_ID=? )and(recondispl2_.PRODUCT_ID=? )and(reconcilia0_.AGE=? )and((reconcilia0_.PENDING_IND is null )or(reconcilia0_.PENDING_IND<>'Y' ))and((reconcilia0_.RECONCILED_IND='U' )OR(reconcilia0_.RECONCILED_IND='N' ))and(reconcilia0_.CUSIP=recondispl2_.CUSIP )and(recondispl2_.CLOSE_SETTL_DTE=? ) group by recondispl2_.PLAN_LBL , reconcilia0_.PLAN , reconcilia0_.CUSIP , securitypl1_.PLAN_NAME , reconcilia0_.TRADE_DATE , reconcilia0_.TRANS_ID , reconcilia0_.SOURCE_DTL



Debug level Hibernate log excerpt:
30 Dec 2004 20:55:06,572 DEBUG SessionImpl - opened session
30 Dec 2004 20:55:06,572 DEBUG SessionImpl - find: select c.planLbl, a.plan, a.cusip, b.planName, a.tradeDate, a.sourceDtl, a.transId, count(a.transId), sum(a.shares) from ReconciliationDtl a left outer join a.sp as b, ReconDisplay c where a.productId = :ProductId and c.productId = :ProductId and a.age = :Age and (a.pendingInd is null or a.pendingInd <> 'Y') and (a.reconciledInd = 'U' OR a.reconciledInd = 'N') and a.cusip=c.reconDisplayPK.cusip and c.reconDisplayPK.closeSettlDte = :endSettlDate group by c.planLbl, a.plan, a.cusip, b.planName, a.tradeDate, a.transId, a.sourceDtl
30 Dec 2004 20:55:06,588 DEBUG QueryParameters - named parameters: {endSettlDate=12/29/2004, ProductId=RS, Age=1}
30 Dec 2004 20:55:06,994 DEBUG QueryTranslator - compiling query
30 Dec 2004 20:55:07,025 DEBUG SessionImpl - flushing session
30 Dec 2004 20:55:07,025 DEBUG SessionImpl - Flushing entities and processing referenced collections
30 Dec 2004 20:55:07,025 DEBUG SessionImpl - Processing unreferenced collections
30 Dec 2004 20:55:07,025 DEBUG SessionImpl - Scheduling collection removes/(re)creates/updates
30 Dec 2004 20:55:07,025 DEBUG SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
30 Dec 2004 20:55:07,041 DEBUG SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
30 Dec 2004 20:55:07,041 DEBUG SessionImpl - Dont need to execute flush
30 Dec 2004 20:55:07,041 DEBUG QueryTranslator - HQL: select c.planLbl, a.plan, a.cusip, b.planName, a.tradeDate, a.sourceDtl, a.transId, count(a.transId), sum(a.shares) from com.ssmb.trex.restricted.model.beans.ReconciliationDtl a left outer join a.sp as b, com.ssmb.trex.restricted.model.beans.ReconDisplay c where a.productId = :ProductId and c.productId = :ProductId and a.age = :Age and (a.pendingInd is null or a.pendingInd <> 'Y') and (a.reconciledInd = 'U' OR a.reconciledInd = 'N') and a.cusip=c.reconDisplayPK.cusip and c.reconDisplayPK.closeSettlDte = :endSettlDate group by c.planLbl, a.plan, a.cusip, b.planName, a.tradeDate, a.transId, a.sourceDtl
30 Dec 2004 20:55:07,041 DEBUG QueryTranslator - SQL: select recondispl2_.PLAN_LBL as x0_0_, reconcilia0_.PLAN as x1_0_, reconcilia0_.CUSIP as x2_0_, securitypl1_.PLAN_NAME as x3_0_, reconcilia0_.TRADE_DATE as x4_0_, reconcilia0_.SOURCE_DTL as x5_0_, reconcilia0_.TRANS_ID as x6_0_, count(reconcilia0_.TRANS_ID) as x7_0_, sum(reconcilia0_.SHARES) as x8_0_ from VMFDB2P.RECONCILIATION_DTL reconcilia0_ left outer join VMFDB2P.SECURITY_PLAN securitypl1_ on reconcilia0_.CUSIP=securitypl1_.CUSIP, VMFDB2P.RECON_DISPLAY recondispl2_ where (reconcilia0_.PRODUCT_ID=? )and(recondispl2_.PRODUCT_ID=? )and(reconcilia0_.AGE=? )and((reconcilia0_.PENDING_IND is null )or(reconcilia0_.PENDING_IND<>'Y' ))and((reconcilia0_.RECONCILED_IND='U' )OR(reconcilia0_.RECONCILED_IND='N' ))and(reconcilia0_.CUSIP=recondispl2_.CUSIP )and(recondispl2_.CLOSE_SETTL_DTE=? ) group by recondispl2_.PLAN_LBL , reconcilia0_.PLAN , reconcilia0_.CUSIP , securitypl1_.PLAN_NAME , reconcilia0_.TRADE_DATE , reconcilia0_.TRANS_ID , reconcilia0_.SOURCE_DTL
30 Dec 2004 20:55:07,041 DEBUG BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
30 Dec 2004 20:55:07,103 DEBUG SQL - select recondispl2_.PLAN_LBL as x0_0_, reconcilia0_.PLAN as x1_0_, reconcilia0_.CUSIP as x2_0_, securitypl1_.PLAN_NAME as x3_0_, reconcilia0_.TRADE_DATE as x4_0_, reconcilia0_.SOURCE_DTL as x5_0_, reconcilia0_.TRANS_ID as x6_0_, count(reconcilia0_.TRANS_ID) as x7_0_, sum(reconcilia0_.SHARES) as x8_0_ from VMFDB2P.RECONCILIATION_DTL reconcilia0_ left outer join VMFDB2P.SECURITY_PLAN securitypl1_ on reconcilia0_.CUSIP=securitypl1_.CUSIP, VMFDB2P.RECON_DISPLAY recondispl2_ where (reconcilia0_.PRODUCT_ID=? )and(recondispl2_.PRODUCT_ID=? )and(reconcilia0_.AGE=? )and((reconcilia0_.PENDING_IND is null )or(reconcilia0_.PENDING_IND<>'Y' ))and((reconcilia0_.RECONCILED_IND='U' )OR(reconcilia0_.RECONCILED_IND='N' ))and(reconcilia0_.CUSIP=recondispl2_.CUSIP )and(recondispl2_.CLOSE_SETTL_DTE=? ) group by recondispl2_.PLAN_LBL , reconcilia0_.PLAN , reconcilia0_.CUSIP , securitypl1_.PLAN_NAME , reconcilia0_.TRADE_DATE , reconcilia0_.TRANS_ID , reconcilia0_.SOURCE_DTL
30 Dec 2004 20:55:07,119 DEBUG BatcherImpl - preparing statement
30 Dec 2004 20:55:07,119 DEBUG StringType - binding '12/29/2004' to parameter: 4
30 Dec 2004 20:55:07,119 DEBUG StringType - binding 'RS' to parameter: 1
30 Dec 2004 20:55:07,119 DEBUG StringType - binding 'RS' to parameter: 2
30 Dec 2004 20:55:07,119 DEBUG IntegerType - binding '1' to parameter: 3
30 Dec 2004 20:55:34,041 DEBUG SessionImpl - running Session.finalize()
30 Dec 2004 20:56:30,869 DEBUG Loader - processing result set
30 Dec 2004 20:56:30,869 DEBUG Loader - result row:
30 Dec 2004 20:56:30,869 DEBUG StringType - returning '80V ' as column: x0_0_
30 Dec 2004 20:56:30,885 DEBUG StringType - returning 'VVV' as column: x1_0_
30 Dec 2004 20:56:30,885 DEBUG StringType - returning '1111111111' as column: x2_0_
30 Dec 2004 20:56:30,885 DEBUG StringType - returning 'QQQQQQQQQQ ' as column: x3_0_
30 Dec 2004 20:56:30,885 DEBUG DateType - returning '23 December 2004' as column: x4_0_
30 Dec 2004 20:56:30,885 DEBUG StringType - returning X' as column: x5_0_
30 Dec 2004 20:56:30,885 DEBUG StringType - returning 'DDDDD ' as column: x6_0_
30 Dec 2004 20:56:30,885 DEBUG IntegerType - returning '4' as column: x7_0_
30 Dec 2004 20:56:30,900 DEBUG StringType - returning '-1.0000' as column: x8_0_
30 Dec 2004 20:56:30,900 DEBUG Loader - done processing result set (1 rows)
30 Dec 2004 20:56:30,900 DEBUG BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
30 Dec 2004 20:56:30,916 DEBUG BatcherImpl - closing statement
30 Dec 2004 20:56:30,916 DEBUG SessionImpl - initializing non-lazy collections
30 Dec 2004 20:56:30,916 DEBUG SessionImpl - closing session
30 Dec 2004 20:56:30,916 DEBUG SessionImpl - disconnecting session
30 Dec 2004 20:56:30,916 DEBUG SessionImpl - transaction completion
30 Dec 2004 20:56:34,431 DEBUG SessionImpl - running Session.finalize()

Greatly appreciate any possible help

You can start by finding out whether the time is spent waiting for the DBMS server to respond or whether the time is spent in Hibernate, building the objects from the result set. If I had to guess, I'd say that it's Hibernate that's waiting for the database to respond. If that's the case, then you need to get a query execution plan from your DBMS so you can index your tables for this type of query. If not, then try using an iterator, lazy loading collections, or using the second level cache.

Hi jdavis,

I run the same query via JDBS, without Hibernate and it runs for 0.2sec. Therefore I assume it is not DBMS server issue. From the log I can see, that time is spend before Hibernate start processing result set.

30 Dec 2004 20:55:34,041 DEBUG SessionImpl - running Session.finalize()
30 Dec 2004 20:56:30,869 DEBUG Loader - processing result set


So I suspect there is something wrong either with my configuration or with my Java code. I am relativly new to both Java and Hiernate. Any hint will be helpful.

Thank you

session finalize closes/cleanup non-closed/cleanedup resources - have you remembered to close/cleanup stuff ?

This is what i have in my code

finally {
if (session.isOpen())
session.close();
}

Is it sufficient?
Did you mean, that i need to have something in my code that prevents from running session.finalize()?

Thank you

hmm - can't understand how you can both a session.finalize and a row processing log entry.....are these entries from the same machine/thread ?

...something on the db side must take 1 minute...use a profiler or debugger to track it down

Hi max,

1. yes, these entries are from the same machine/thread.
2. when i run the same SQL from the application without Hibernate, it takes 0.2 sec. same result running it interactivly.

can yu see anything wrong in my code (posted in the beginning)?

Thank you

why don't you look into it since hibernate does much more than just execute the query - but it shouldnt be much slower unless eg. your session contains thousands of objects it need to process etc.

something else is affecting this...