Performance of 3.2.3 When EJB requires DB lookup

[lucasfowler]

We have upgraded an application from 3.0.8 to 3.2.3 and are experiencing
performance issues in an EJB which requires a secondary key and therefore
doesn't use the default finder.

Basically we have a bean which provides a bi-directional map for two id's.

In one direction, the beans can be cached on the PK and the operation takes under
1 millisecond, but in the opposite direction it takes between 8-20 ms and the CPU
hits 100% load.

Our database is PostgreSQL and I have run an explain for the required
statements and I find that both lookups require about 0.1 ms(!) because
both lookups are keyed.

So my assumption is that the EJB/JDBC request is taking all the time.

Can anyone give us some pointers as to parameters which would help to
tune this operation and/or which modules we should turn on tracing for
to see where the time is being used.

If you need more info, I can post logfiles

Thanks

[lucasfowler]

Follow up

The bit about 100% CPU seems to be due to the JMS which was going on (We were using OIL on 3.0.8 and UIL2 on 3.2.3, see my post in the JMS forum which I'll post after this).

But the rest still holds true.

[juha]

Yes trace will be useful, also you should ping on the CMP forum and see if Alex picks it up, or if you have a minimal test case to demonstrate the performance issue then post it via Sourceforge bug tracker.

[aloubyansky]

W/o looking at SQL it is impossible to say what the problem is. Perhaps, it is using joins for the opposite direction. I am not saying it takes that long but I can't say it isn't neither.
It would also help if you could compare the SQL from 3.0.8 and 3.2.3 and let us know how long it took in 3.0.8.

[lucasfowler]

OK, the trace is below, as well as the explain from Postgres.

I had a closer look at the times and I'm seeing that 20ms is a peak,
the trace below is more like the mode, about 3ms, with an average
of about 8ms.

Still 3ms for a request which Postgres manages in 0.13ms is still rather large.

----------------------------------------------------------------------------
xcdm01=# explain analyze SELECT t0_t.member_id, t0_t.trader_id, t0_t.exchange_id FROM trader_mapping t0_t WHERE (t0_t.exchange_trader_id = '17664' AND t0_t.exchange_id = 'swx') ;
NOTICE: QUERY PLAN:

Seq Scan on trader_mapping t0_t (cost=0.00..1.48 rows=1 width=30) (actual time=0.08..0.08 rows=0 loops=1)
Total runtime: 0.13 msec

----------------------------------------------------------------------------

[2004-03-26 18:11:41,229] [INFO ] [SequenceRule] Applying rule MapExchangeTraderIdToEquityTraderId to SubscribeInquireResponse[ Order;s=queue/macd/Gateway:Exchange:vtx:TsxReceiver:-;t=queue/macd/Gateway:TrendServer:trdmdmo:2A426BAB812A6D7ACC1D947826B647E8;-----E;144;132617;#0;status(0;;);[ vtx;GB0002634946;GBX;GLOX Test 3.17;B;Wed Mar 24 18:26:25 CET 2004;Wed Mar 24 18:26:25 CET 2004;1;null;true;null;17664;40271;null;169373;null;N;null;Wed Mar 24 00:00:00 CET 2004;C;null;true;0.25;null; ;null;T;D;N;10;null;O;null;null;0;0]]
[2004-03-26 18:11:41,229] [TRACE] [org.jboss.ejb.plugins.LogInterceptor] Start method=findByTraderIdAndExchange
[2004-03-26 18:11:41,229] [TRACE] [org.jboss.ejb.plugins.TxInterceptorCMT] Current transaction in MI is null
[2004-03-26 18:11:41,230] [TRACE] [org.jboss.ejb.plugins.TxInterceptorCMT] TX_NOT_SUPPORTED for findByTraderIdAndExchange
[2004-03-26 18:11:41,230] [TRACE] [org.jboss.ejb.plugins.TxInterceptorCMT] Thread came in with tx null
[2004-03-26 18:11:41,230] [TRACE] [org.jboss.ejb.plugins.EntityInstancePool] Get instance org.jboss.ejb.plugins.EntityInstancePool@9e40d2#1#class com.macd.xConnect.ejbeans.tradermapping.TraderMappingBean
[2004-03-26 18:11:41,230] [DEBUG] [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.TraderMapping#findByTraderIdAndExchange] Executing SQL: SELECT t0_t.member_id, t0_t.trader_id, t0_t.exchange_id FROM trader_mapping t0_t WHERE (t0_t.exchange_trader_id = ? AND t0_t.exchange_id = ?)
[2004-03-26 18:11:41,231] [TRACE] [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.TraderMapping#findByTraderIdAndExchange] Set parameter: index=1, jdbcType=VARCHAR, value=17664
[2004-03-26 18:11:41,231] [TRACE] [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.TraderMapping#findByTraderIdAndExchange] Set parameter: index=2, jdbcType=VARCHAR, value=vtx
[2004-03-26 18:11:41,234] [TRACE] [org.jboss.ejb.plugins.EntityInstancePool] 0/100 Free instance:org.jboss.ejb.plugins.EntityInstancePool@9e40d2#null#null#false#class com.macd.xConnect.ejbeans.tradermapping.TraderMappingBean
[2004-03-26 18:11:41,234] [TRACE] [org.jboss.ejb.plugins.LogInterceptor] End method=findByTraderIdAndExchange

[aloubyansky]

If I understand right, 0.13 msec is the time that Postgres took to execute the query. It does not take into account JDBC, right?
How long did it take in 3.0.8?
Thanks.

[lucasfowler]

Yes, that's right, the 3ms is between

[2004-03-26 18:11:41,231] [TRACE] [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.TraderMapping#findByTraderIdAndExchange] Set parameter: index=2, jdbcType=VARCHAR, value=vtx

and

[2004-03-26 18:11:41,234] [TRACE] [org.jboss.ejb.plugins.EntityInstancePool] 0/100 Free instance:org.jboss.ejb.plugins.EntityInstancePool@9e40d2#null#null#false#class com.macd.xConnect.ejbeans.tradermapping.TraderMappingBean

Is there any tracing for this bit I can turn on?