6 Replies Latest reply on Mar 29, 2004 7:14 AM by lucasfowler

    Performance of 3.2.3 When EJB requires DB lookup

    lucasfowler Newbie

      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

        • 1. Re: Performance of 3.2.3 When EJB requires DB lookup
          lucasfowler Newbie

          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.

          • 2. Re: Performance of 3.2.3 When EJB requires DB lookup
            Juha Lindfors Master

            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.

            • 3. Re: Performance of 3.2.3 When EJB requires DB lookup
              Alexey Loubyansky Master

              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.

              • 4. Re: Performance of 3.2.3 When EJB requires DB lookup
                lucasfowler Newbie

                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

                • 5. Re: Performance of 3.2.3 When EJB requires DB lookup
                  Alexey Loubyansky Master

                  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.

                  • 6. Re: Performance of 3.2.3 When EJB requires DB lookup
                    lucasfowler Newbie

                    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?