Bugs item #925597, was opened at 2004-03-29 14:35
Message generated for change (Comment added) made by jacyg
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=376685&aid=925597&group_id=22866
Category: JBossCMP
Group: v3.2
Status: Open
Resolution: None
Priority: 5
Submitted By: Jacy Grannis (jacyg)
Assigned to: Alexey Loubyansky (loubyansky)
Summary: Problem with JDBCLoadEntityCommand in 3.2.4
Initial Comment:
There seems to be a problem with using finders in
3.2.4. After the finder has been run, the loader
iteratively calls sql statements to load each
individual bean, and ends up generating quite a lot of
unnecessary sql statements. I'm running 3.2.4rc1 under
java 1.4.2_01-b06. I've included a snippet from my
logs that illustrates the problem. The "Classes" bean
(which is merely an example, I see the same behaviour
with all my entity beans) has 4 fields, a Long primary
key, a String name, a Long type_id, and a String
description. I rather doubt that has much to do with
it, since this behaviour doesn't exist in 3.2.1, but in
case you were wondering. We are using the standard cmp
configuration, with the exception of changing our
strategy to "on-find" instead of "on-load". The
observed behaviour makes 3.2.4 pretty much unusable for
doing entity beans b/c it *seriously* slows things
down. Let me know if you have any questions.
(log messages attached, nothing snipped or anything,
it's exactly as it showed up)
----------------------------------------------------------------------
>Comment By: Jacy Grannis (jacyg)
Date: 2004-05-25 14:11
Message:
Logged In: YES
user_id=711020
For my own edification, I added stack traces into the load()
method so I could see what is happening. Here are the tails
of the stack traces that show the two invocations on a bean
like I described:
java.lang.Throwable: IN LOAD SUCCESS
at
org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.load(ReadAheadCache.java:420)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.execute(JDBCLoadEntityCommand.java:110)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.execute(JDBCLoadEntityCommand.java:72)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.loadEntity(JDBCStoreManager.java:620)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.loadEntity(JDBCStoreManager.java:602)
at
org.jboss.ejb.plugins.CMPPersistenceManager.loadEntity(CMPPersistenceManager.java:355)
at
org.jboss.resource.connectionmanager.CachedConnectionInterceptor.loadEntity(CachedConnectionInterceptor.java:352)
at
org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:261)
at
org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:185)
at
org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:118)
at
org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:175)
at
org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:89)
at
org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:54)
at
org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:84)
at
org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:316)
at
org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:149)
at
org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:118)
at
org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:191)
at
org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
at
org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:484)
at org.jboss.ejb.Container.invoke(Container.java:713)
at
org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:375)
at
org.jboss.ejb.plugins.local.EntityProxy.invoke(EntityProxy.java:44)
at $Proxy635.getId(Unknown Source)
java.lang.Throwable: IN LOAD FAILED
at
org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.load(ReadAheadCache.java:321)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.execute(JDBCLoadEntityCommand.java:110)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.execute(JDBCLoadEntityCommand.java:72)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.loadEntity(JDBCStoreManager.java:620)
at
org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.loadEntity(JDBCStoreManager.java:602)
at
org.jboss.ejb.plugins.CMPPersistenceManager.loadEntity(CMPPersistenceManager.java:355)
at
org.jboss.resource.connectionmanager.CachedConnectionInterceptor.loadEntity(CachedConnectionInterceptor.java:352)
at
org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:261)
at
org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:185)
at
org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:118)
at
org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:175)
at
org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:89)
at
org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:54)
at
org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:84)
at
org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:316)
at
org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:149)
at
org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:118)
at
org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:191)
at
org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
at
org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:484)
at org.jboss.ejb.Container.invoke(Container.java:713)
at
org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:375)
at
org.jboss.ejb.plugins.local.EntityProxy.invoke(EntityProxy.java:44)
at $Proxy635.getType(Unknown Source)
----------------------------------------------------------------------
Comment By: Jacy Grannis (jacyg)
Date: 2004-05-25 14:09
Message:
Logged In: YES
user_id=711020
Oh, well, my bad, I just was continuing to investigate so I
could try to patch it at least for myself. It's not the
JDBCCMRFieldBridge , that was a mistake on my part. I had
added logging to determine when the load() method was
getting invoked and saw that it was being invoked multiple
times, and assumed it was getting invoked from somewhere
else. In fact, the problem is that if you are using a bean
with more than one field, the access to the extra fields is
what causes the failure. Try a bean with a single field PK,
and two other fields, and you will see the behaviour. For
example, take a bean with three fields: id, name,
description, where id is the pk. then, run something, such
as your find all. When iterating, call getId(), getName(),
getDescription(), you will see multiple queries being
invoked. Also, you bring discredit to your project by so
summarily dismissing the bug, the logs I originally posted
should be plenty of evidence that something is, in fact,
going on that shouldn't be. By continuing to close this bug
you are only diminishing the chances that jboss will get
fixed and be as robust as you (and I) would like it to be.
Maybe it strains your belief that this is a bug, but it is.
----------------------------------------------------------------------
Comment By: Alexey Loubyansky (loubyansky)
Date: 2004-05-25 12:48
Message:
Logged In: YES
user_id=543482
Ok then I find it hard to believe that it is a bug in JBoss
(3.2.4RC2). It works for me. Re-open when you have a testcase.
<query>
<query-method>
<method-name>findAll</method-name>
<method-params>
</method-params>
</query-method>
<jboss-ql><![CDATA[select object(o) from B o]]></jboss-ql>
<read-ahead>
<strategy>on-find</strategy>
<page-size>5</page-size>
<eager-load-group>*</eager-load-group>
</read-ahead>
</query>
Iterator i = BUtil.getLocalHome().findAll().iterator();
while(i.hasNext())
{
BLocal b = (BLocal)i.next();
log.info("b.name=" + b.getName());
}
20:45:52,705 DEBUG [B#findAll] Executing SQL: SELECT
t0_o.id, t0_o.name, t0_o.intField, t0_o.dateField, t0_o.b
inData, t0_o.A_FK FROM B t0_o
20:45:52,715 DEBUG [BBean] ejbLoad for 11
20:45:52,715 INFO [FacadeSessionBean] b.name=null
20:45:52,715 DEBUG [BBean] ejbLoad for 22
20:45:52,715 INFO [FacadeSessionBean] b.name=null
20:45:52,715 DEBUG [BBean] ejbLoad for 33
20:45:52,715 INFO [FacadeSessionBean] b.name=null
----------------------------------------------------------------------
Comment By: Jacy Grannis (jacyg)
Date: 2004-05-25 10:49
Message:
Logged In: YES
user_id=711020
I find it hard to believe that reading this bug report
doesn't give enough information... Run *any* finder on a
CMP bean that returns more than 1 result with the load
strategy set to on-find. That will reproduce this bug. It
happens with all our beans, as I stated before. Our CMP
configuration is the same as the standard config, except we
are using on-find instead of on-load (though I believe you
would also see similar problems with on-load, but haven't
confirmed that).
----------------------------------------------------------------------
Comment By: Alexey Loubyansky (loubyansky)
Date: 2004-05-25 01:49
Message:
Logged In: YES
user_id=543482
Please, provide a testcase or detailed instructions to
reproduce.
----------------------------------------------------------------------
Comment By: Jacy Grannis (jacyg)
Date: 2004-05-24 17:56
Message:
Logged In: YES
user_id=711020
I've found the root of this problem. The problem has to do
with the ReadAheadCache being used in multiple places. In
particular, the load() method of the ReadAheadCache. What
happens is this: in the course of the entity call, the
JDBCCMRFieldBridge calls the load() method. At the end of
the load() method, it clears out the cache for that id.
Then, later in the course of that invocation, the
JDBCLoadEntityCommand also calls load(). This returns false
b/c the data has already been cleared out of the cache by
the earlier load(). Then, because the load() returned
false, it reruns the query to load the data up. I'm not
sure what the proper resolution of this is, but it is
definitely a serious issue with CMP.
----------------------------------------------------------------------
Comment By: Jacy Grannis (jacyg)
Date: 2004-03-30 10:04
Message:
Logged In: YES
user_id=711020
Sure. Here is the method, it is in a stateless session bean
that is using CMT.
<code>
/**
* @ejb.interface-method
* Method findClazzes
*
* @param type
*
* @return
*
* @throws FuelQuestException
*
*/
public Collection findClazzes(ClazzType type) throws
FuelQuestException
{
try
{
Collection col =
classHome.findByClazzTypeId(type.getId().getValue());
if ((col == null) || (col.size() == 0))
{
return Collections.EMPTY_LIST;
}
else
{
List list = new ArrayList(col.size());
for (Iterator it = col.iterator(); it.hasNext(); )
{
list.add(getClazzImpl((LocalClazzes)it.next()));
}
return list;
}
}
catch (FinderException fe)
{
super.setRollbackOnly();
throw new FuelQuestException("Error getting classes.", fe);
}
}</code>
----------------------------------------------------------------------
Comment By: Alexey Loubyansky (loubyansky)
Date: 2004-03-30 01:00
Message:
Logged In: YES
user_id=543482
Could you post the code that triggers this SQL?
----------------------------------------------------------------------
Comment By: Jacy Grannis (jacyg)
Date: 2004-03-29 15:55
Message:
Logged In: YES
user_id=711020
furthermore, since this behaviour didn't exist before,
before it would run the finder and then a SINGLE query to
load up the entities, this would be a bug, and should be
addressed. CMP under jboss is unusable otherwise.
----------------------------------------------------------------------
Comment By: Jacy Grannis (jacyg)
Date: 2004-03-29 15:53
Message:
Logged In: YES
user_id=711020
I've read your CMP docs, multiple times. It shouldn't be
running a query for each row returned by the finder. It
should have been able to load them in a single query. Did
you even look at the log statements?
----------------------------------------------------------------------
Comment By: Alexey Loubyansky (loubyansky)
Date: 2004-03-29 15:08
Message:
Logged In: YES
user_id=543482
Please, read our CMP docs.
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=376685&aid=925597&group_id=22866
-------------------------------------------------------
This SF.Net email is sponsored by: Oracle 10g
Get certified on the hottest thing ever to hit the market... Oracle 10g.
Take an Oracle 10g class now, and we'll give you the exam FREE.
http://ads.osdn.com/?ad_id=3149&alloc_id=8166&op=click
_______________________________________________
JBoss-Development mailing list
[EMAIL PROTECTED]
https://lists.sourceforge.net/lists/listinfo/jboss-development
