Hello again JBoss people.
Our "e-mall" is almost ready for consumers.
The first test-stores are on-line and making test's to the system.
Our own tests are also running fine, we make small progress every day,
getting more experience with JBoss and the EJB concept.
We do however have one question -
We are using a resultset to select items from the mall to the customer.
At first we had a SQLManager object inside JBoss which made the
select-statement, remembered the resultset, and we called nextRecord etc. on
this object. This is really slow, but is very generel, and easy to use.
So - the first optimization step was to return the resultset to the bean,
and let the bean traverse the resultset.
This made the select much faster, and currently we are using this feature.
BUT - we noticed that when we force the browser to load pages before the
last one finished, the DBpool is drained. The code that should return the
connection to the pool is never called.
After studying our log-files, we notice that the connection from the bean to
the JBoss stateless session bean.
Here are the log files with comments:
The number in () is a bean-id so we can follow this bean through the system.
this section is a "good" example
10:21:05,307 DEBUG JSP:ShowItems - (987754865307) Will get webData
10:21:05,307 DEBUG ItemPriceBean - (beanId=987754865307)
getWebDataByCategoryAndStore(13,null)
10:21:05,397 DEBUG ItemPriceBean - (beanId=987754865307) Successfully
got ref to itemPriceDAOEJB
10:21:05,407 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307)
selectResultSet - Start
10:21:05,407 INFO root InterBaseDB - No transaction right now.
10:21:05,407 INFO root InterBaseDB - Pool InterBaseDB [1/1/10] gave out
pooled object: org.opentools.minerva.jdbc.xa.wrapper.XAConnectionImpl@45f743
10:21:05,407 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) Got
'java:comp/env/jdbc/DBPool' handle
10:21:05,407 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) Did
_conn.createStatement()
10:21:05,407 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307)
selectResultSet - Did initDB
10:21:05,417 INFO ItemPriceDAOEJBBean - (beanId=987754865307) Executing
query...: SELECT NAME, ITEMID, PRICE, PICTURE, STOREID, DESCRIPTION FROM
ITEMPRICEEJB WHERE CATEGORYID = 13 AND STOREID = 'null' AND NAME !=''
10:21:06,078 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307)
selectResultSet - Did query....returning
10:21:06,078 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) --All
closed!-- (context that is!)
10:21:06,078 DEBUG ItemPriceBean - (beanId=987754865307) Time to fetch
data (JavaBean layer): 671
10:21:06,088 DEBUG ItemPriceBean - (beanId=987754865307) retrieved 6
items
10:21:06,088 DEBUG JSP:ShowItems - (987754865307) Time to fetch data
(JSP layer): 781
10:21:06,088 DEBUG JSP:ShowItems - (987754865307)
itemprice.gotoNextItem()
10:21:06,088 DEBUG JSP:ShowItems - (987754865307)
itemprice.gotoNextItem() proceed=false
10:21:06,088 DEBUG JSP:ShowItems - (987754865307)
itemprice.gotoNextItem() closeSelect
10:21:06,088 DEBUG ItemPriceBean - (beanId=987754865307) Closing
resultset
10:21:06,088 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) Close
resultSet???
10:21:06,088 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) please
Close resultSet
10:21:06,088 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) Close
statement???
10:21:06,088 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) please
Close statement
10:21:06,088 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) Close
Connection???
10:21:06,088 DEBUG ItemPriceDAOEJBBean - (beanId=987754865307) please
Close connection
10:21:06,088 INFO root InterBaseDB - Pool InterBaseDB [0/1/10] returned
object org.opentools.minerva.jdbc.xa.wrapper.XAConnectionImpl@45f743 to the
pool.
10:21:06,088 DEBUG JSP:ShowItems - (987754865307)
itemprice.gotoNextItem() closeSelect - done
So - all it did finish OK!
The next scenario is when is click the same category so quickly that the
first cycle is not finished.
10:21:26,858 DEBUG JSP:ShowItems - (987754886858) Store not defined,
will only get data based on category
10:21:26,878 DEBUG JSP:ShowItems - (987754886858) Will get webData
10:21:26,878 DEBUG ItemPriceBean - (beanId=987754886858)
getWebDataByCategoryAndStore(29,-1)
10:21:26,898 DEBUG ItemPriceBean - (beanId=987754886858) Successfully
got ref to itemPriceDAOEJB
10:21:26,898 DEBUG ItemPriceDAOEJBBean - (beanId=987754886858)
selectResultSet - Start
10:21:26,908 INFO root InterBaseDB - No transaction right now.
10:21:26,908 INFO root InterBaseDB - Pool InterBaseDB [1/1/10] gave out
pooled object: org.opentools.minerva.jdbc.xa.wrapper.XAConnectionImpl@45f743
10:21:26,908 DEBUG ItemPriceDAOEJBBean - (beanId=987754886858) Got
'java:comp/env/jdbc/DBPool' handle
10:21:26,908 DEBUG ItemPriceDAOEJBBean - (beanId=987754886858) Did
_conn.createStatement()
10:21:26,908 DEBUG ItemPriceDAOEJBBean - (beanId=987754886858)
selectResultSet - Did initDB
10:21:26,908 INFO ItemPriceDAOEJBBean - (beanId=987754886858) Executing
query...: SELECT NAME, ITEMID, PICTURE, STOREID, DESCRIPTION FROM
ITEMPRICEEJB WHERE CATEGORYID = 29 AND NAME !=''
10:21:26,948 DEBUG ItemPriceDAOEJBBean - (beanId=987754886858)
selectResultSet - Did query....returning
10:21:26,948 DEBUG ItemPriceDAOEJBBean - (beanId=987754886858) --All
closed!-- (This is the context used to get the connection)
10:21:26,948 DEBUG ItemPriceBean - (beanId=987754886858) Time to fetch
data (JavaBean layer): 50
10:21:26,948 DEBUG ItemPriceBean - (beanId=987754886858) retrieved 5
items
10:21:26,948 DEBUG JSP:ShowItems - (987754886858) Time to fetch data
(JSP layer): 70
10:21:26,948 DEBUG JSP:ShowItems - (987754886858)
itemprice.gotoNextItem()
10:21:26,948 DEBUG JSP:ShowItems - (987754886858)
itemprice.gotoNextItem() proceed=true
//Here the next "click" starts! (Now we got the ..858 and the ..429 running!
10:21:27,439 DEBUG JSP:ShowItems - (987754887429) Store not defined,
will only get data based on category
10:21:27,469 DEBUG JSP:ShowItems - (987754887429) Will get webData
10:21:27,479 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429)
selectResultSet - Start
//The first one is finished!
10:21:27,759 DEBUG JSP:ShowItems - (987754886858)
itemprice.gotoNextItem() done while statement - end the jsp page!
10:21:27,759 DEBUG JSP:ShowItems - (987754886858)
itemprice.gotoNextItem() closeSelect
10:21:27,759 DEBUG ItemPriceBean - (beanId=987754886858) Closing
resultset
//Here is get's strange. The beanId is gone - meaning is it a new
ItemPriceDAOEJBBean object.
10:21:27,759 DEBUG ItemPriceDAOEJBBean - () Close resultSet???
10:21:27,759 DEBUG ItemPriceDAOEJBBean - () resultSet == null
10:21:27,759 DEBUG ItemPriceDAOEJBBean - () Close statement???
10:21:27,759 DEBUG ItemPriceDAOEJBBean - () statement == null
10:21:27,759 DEBUG ItemPriceDAOEJBBean - () Close Connection???
10:21:27,759 DEBUG ItemPriceDAOEJBBean - () connection == null
10:21:27,759 DEBUG JSP:ShowItems - (987754886858)
itemprice.gotoNextItem() closeSelect - done
I put the next part of the log-file in here to show that the ...429 is
closing normally even when a new cycle is starting.
The useBean statement in our JSP is Request (we also had a session to try it
out!)
The ItemPriceDAOEJBBean is a stateless session bean.
Can anyone explain why this goes wrong ?
AND please do not say : "dont do it like that!".
We are running JBoss 2.2
Jetty 3.1 RC 2
Interbase 6
W2K host
------------rest of log------------------
10:21:28,120 DEBUG JSP:ShowItems - (987754888120) Store not defined,
will only get data based on category
10:21:28,120 DEBUG JSP:ShowItems - (987754888120) Will get webData
10:21:28,120 DEBUG ItemPriceBean - (beanId=987754888120)
getWebDataByCategoryAndStore(29,-1)
10:21:28,130 DEBUG ItemPriceBean - (beanId=987754888120) Successfully
got ref to itemPriceDAOEJB
10:21:28,130 DEBUG ItemPriceDAOEJBBean - (beanId=987754888120)
selectResultSet - Start
10:21:28,710 DEBUG JSP:ShowItems - (987754888710) Store not defined,
will only get data based on category
10:21:28,710 DEBUG JSP:ShowItems - (987754888710) Will get webData
10:21:28,710 DEBUG ItemPriceBean - (beanId=987754888710)
getWebDataByCategoryAndStore(29,-1)
10:21:28,741 DEBUG ItemPriceBean - (beanId=987754888710) Successfully
got ref to itemPriceDAOEJB
10:21:28,741 DEBUG ItemPriceDAOEJBBean - (beanId=987754888710)
selectResultSet - Start
10:21:28,761 INFO root InterBaseDB -
org.opentools.minerva.jdbc.xa.wrapper.XADataSourceImpl created new
Connection (interbase.interclient.Connection) with XAResource
org.opentools.minerva.jdbc.xa.wrapper.XAResourceImpl and XAConnection
org.opentools.minerva.jdbc.xa.wrapper.XAConnectionImpl.
10:21:28,761 INFO root InterBaseDB - No transaction right now.
10:21:28,761 INFO root InterBaseDB - Pool InterBaseDB [1/1/10] gave out new
object: org.opentools.minerva.jdbc.xa.wrapper.XAConnectionImpl@61fcdd
10:21:28,771 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) Got
'java:comp/env/jdbc/DBPool' handle
10:21:28,771 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) Did
_conn.createStatement()
10:21:28,771 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429)
selectResultSet - Did initDB
10:21:28,771 INFO ItemPriceDAOEJBBean - (beanId=987754887429) Executing
query...: SELECT NAME, ITEMID, PICTURE, STOREID, DESCRIPTION FROM
ITEMPRICEEJB WHERE CATEGORYID = 29 AND NAME !=''
10:21:28,951 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429)
selectResultSet - Did query....returning
10:21:28,951 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) --All
closed!--
10:21:28,951 DEBUG ItemPriceBean - (beanId=987754887429) Time to fetch
data (JavaBean layer): 1472
10:21:28,951 DEBUG ItemPriceBean - (beanId=987754887429) retrieved 5
items
10:21:28,951 DEBUG JSP:ShowItems - (987754887429) Time to fetch data
(JSP layer): 1502
10:21:28,951 DEBUG JSP:ShowItems - (987754887429)
itemprice.gotoNextItem() Used as itemPrice.first() because jdbc driver is
not 2.0 compliant
10:21:28,951 DEBUG JSP:ShowItems - (987754887429)
itemprice.gotoNextItem() proceed=true
10:21:29,161 DEBUG JSP:ShowItems - (987754887429)
itemprice.gotoNextItem() done while statement - end the jsp page!
10:21:29,161 DEBUG JSP:ShowItems - (987754887429)
itemprice.gotoNextItem() closeSelect
10:21:29,161 DEBUG ItemPriceBean - (beanId=987754887429) Closing
resultset
10:21:29,161 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) Close
resultSet???
10:21:29,161 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) please
Close resultSet
10:21:29,161 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) Close
statement???
10:21:29,161 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) please
Close statement
10:21:29,161 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) Close
Connection???
10:21:29,161 DEBUG ItemPriceDAOEJBBean - (beanId=987754887429) please
Close connection
10:21:29,171 INFO root InterBaseDB - Pool InterBaseDB [1/2/10] returned
object org.opentools.minerva.jdbc.xa.wrapper.XAConnectionImpl@61fcdd to the
pool.
10:21:29,171 DEBUG JSP:ShowItems - (987754887429)
itemprice.gotoNextItem() closeSelect - done
- René Rolander Nygaard
winmail.dat
