Menu
▾
▴
#1811 Problem with JDBCLoadEntityCommand in 3.2.4
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)
log statements showing the multiple sql statements that are being executed
Logged In: YES
user_id=543482
Please, read our CMP docs.
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?
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.
Logged In: YES
user_id=543482
Could you post the code that triggers this SQL?
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>
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.
Logged In: YES
user_id=543482
Please, provide a testcase or detailed instructions to
reproduce.
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).
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
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.
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)
Logged In: YES
user_id=543482
Like this?
Iterator i = BUtil.getLocalHome().findAll().iterator();
while(i.hasNext())
{
BLocal b = (BLocal)i.next();
log.info("b.name=" + b.getId() + " " + b.getName()
+ " " + b.getIntField());
}
22:48:48,531 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
22:48:48,541 DEBUG [BBean] ejbLoad for 11
22:48:48,541 INFO [FacadeSessionBean] b.name=11 null null
22:48:48,541 DEBUG [BBean] ejbLoad for 22
22:48:48,541 INFO [FacadeSessionBean] b.name=22 null null
22:48:48,541 DEBUG [BBean] ejbLoad for 33
22:48:48,551 INFO [FacadeSessionBean] b.name=33 null null
Logged In: YES
user_id=543482
Are you using the following in jboss.xml?
<method-attributes>
<method>
<method-name>get*</method-name>
<read-only>true</read-only>
</method>
</method-attributes>
Logged In: YES
user_id=711020
yes. at one point, that was recommended. has that changed?
Logged In: YES
user_id=543482
This is what called details as it's not the default config.
This <read-only> behaviour changed awhile ago. It is the
same at least in 3.2.3.
What is happenning is that a read-only (jboss.xml)
invocation does not associate the target instance with the
transaction and the instance is discarded and thrown away
from the cache (unless commit option A) at the end of the
invocation.
Read-ahead cache is a cache per transaction. It means for
read-only invocations, read-ahead cache is a cache per
invocation. It is the same as running w/o transactions for
read-only=false invocations.
Logged In: YES
user_id=711020
fair enough...except that the jboss docs say that the
read-only attribute on method-attributes is to prevent
bean-locking, not to do anything to affect the caching
behaviour...
Logged In: YES
user_id=711020
at any rate, i don't see any point to keeping this open. i
would, however, state that i also *really* don't see the
point of the read-only option if it breaks all the loading
strategy stuff. if you can't use your load groups or
on-find, you lose *all* the benefits of having
read-only...yeah, you're saving a lock, but you're vastly
increasing the amount of work the server is doing because it
has to go to the database n x m more times (where n is # of
beans and m is # of read-only fields). which, i guess, is
fine to not have the read-only option, but it becomes useful
only to people who are using commit option A instead of
being more broadly useful like it used to be and hopefully
saving some computation time that is involved with acquiring
and (maybe) waiting for bean locks.