8 Replies Latest reply on Apr 2, 2012 8:06 AM by Aleš Bregar

    Weird preformance degradation encounter on servlet-ejb-ejb call

    Aleš Bregar Newbie

      Hi,

       

      recently I put more focus on benchmarking my app (based on as 7.1.1.Final) and some weird stuff popped out (at least from my point of view). Scenario is the following:

      - servlet with CDI injected SLSB ejb (local interface)

      - ejb has other SLSB ejb injected and some JPA repository is called from method1 also

       

      With some pinpointing I see the issue when ejb2.method2 is called from ejb1 and method execution is rather fast(~1ms), but returning from that method2 back to bean1 takes quite long time. I got TRACE on that point and some interesting transaction handshake is going on for a long time. Please see the attached log snippet (the diff at the end is one of the largest captured, on average it takes ~100-200ms for this handshake).

       

      I would be really glad to hear the opinion on what I am doing wrong or have misconfigured.

       

      Thank you in advance,

      A

        • 1. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
          Stephen Coy Master

          Remember that most database writes happen at transaction commit time.

          • 2. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
            Aleš Bregar Newbie

            Tnx on the idea Stephen,

             

            but I am pretty sure that here are no db writes in the above posted method chain.

            Any other idea where to look at?

            • 3. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
              Tomaz Cerar Master

              Hi,

               

              Can you try run it with profiler (tracing is better than sampling) so we we can see where the real problem lies.

              It might be slow jurnal on disk or something completly else.

               

              --

              tomaz

              • 4. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
                Stephen Coy Master

                You might try setting:

                 

                     hibernate.show_sql = true

                 

                and checking what queries are issued at commit time.

                • 5. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
                  Aleš Bregar Newbie

                  @Tomaz

                   

                  Good idea to propose profiling, so here are some interesting result(s) from two blocked http threads:

                   

                  org.jboss.logmanager.handlers.WriterHandler.doPublish(ExtLogRecord) 
                  480ms 77%
                  
                  org.jboss.logmanager.Logger.logRaw(ExtLogRecord)
                  org.slf4j.impl.Slf4jLogger.info(String)
                  ...
                  
                  org.jboss.jca.adapters.jdbc.xa.XAManagedConnectionFactory.createManagedConnection(Subject, ConnectionRequestInfo) 145ms 23%
                  org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection()
                  ...
                  ---------------------------
                  
                  org.jboss.logmanager.handlers.WriterHandler.doPublish(ExtLogRecord) 
                  330ms 62%
                  
                  org.jboss.logmanager.Logger.logRaw(ExtLogRecord)
                  org.slf4j.impl.Slf4jLogger.info(String)
                  ...
                  
                  org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.getConnectionProperties(Subject, ConnectionRequestInfo)
                  200ms 38%
                  
                  org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection()
                  ...
                  

                   

                  other blocked http threads involve the combination of the two options above.

                   

                   

                  I would have two questions based on the above:

                  1. what can I do to optimize the logger (do you know if there is any issue on slf4j?)?

                  2. that is how I do xa-datasource setup from subsystem:

                   

                  <xa-datasource jndi-name="java:jboss/datasources/mcore" pool-name="mcore" enabled="true">
                      <xa-datasource-property name="URL">
                          jdbc:oracle:thin:@//dbip
                      </xa-datasource-property>
                      <xa-datasource-property name="User">
                          user
                      </xa-datasource-property>
                      <xa-datasource-property name="Password">
                          pass
                      </xa-datasource-property>
                      <driver>oracle</driver>
                      <xa-pool>
                          <min-pool-size>2</min-pool-size>
                          <max-pool-size>6</max-pool-size>
                          <prefill>true</prefill>
                      </xa-pool>
                      <timeout>
                          <blocking-timeout-millis>5000</blocking-timeout-millis>
                          <idle-timeout-minutes>1</idle-timeout-minutes>
                      </timeout>
                  </xa-datasource>
                  

                   

                  Is there something wrong with this as it seems that it takes very long sometimes(always?) to get connection from the pool?

                   

                   

                  BTW: all tried/profiled by using 7.1.2 nightly 814

                   

                  Thanks on any hint,

                  A

                  • 6. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
                    Stephen Coy Master

                    The pool sizes seem small. 

                     

                    Are you profiling under load with multiple incoming requests?

                     

                    Threads will block waiting for connections when the pool is exhausted.

                     

                    You may be seeing a similar issue with logging, because ultimately only one thread to can write to the log file at one time. Previous versions of JBoss supported an asynchronous logger appender which basically queued log messages and returned, with a secondary thread being responsible for writing to the log file. If you have a look at the jboss-as-logging_1_1.xsd file you will see that it allows you to specify an "async-handler" which presumably has similar behaviour.

                    • 7. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
                      Tomaz Cerar Master

                      I agree that using async logger would improve your results, especialy if you are running on slow disks (EC2 if i remember corectly)

                       

                      config for async should look something like this:

                       

                      the definitnion of logger

                      <async-handler name="ASYNC">

                                      <queue-length value="5"/>

                                      <subhandlers>

                                          <handler name="FILE"/>

                                      </subhandlers>

                                  </async-handler>

                      and then

                              

                      <root-logger>

                                      <level name="INFO"/>

                                      <handlers>

                                          <handler name="ASYNC"/>

                                      </handlers>

                                  </root-logger>

                       

                      you don't need extra logging to console or to file, as it will just additionaly slow down the system.

                       

                       

                      --

                      tomaz

                      • 8. Re: Weird preformance degradation encounter on servlet-ejb-ejb call
                        Aleš Bregar Newbie

                        Tnx both.

                         

                        I have introduced:

                        - async logging on file

                        - removed console logging

                        - introduced larger pool size for datasource(s) (set max-pool-size=20)

                        - introduce 'prepared-statement-cache-size' in standalone.xml

                        - introduce 'share-prepared-statements' in standalone.xml

                        - introduce L2C on persistence in persistence.xml

                        - introduce query cache in persistence.xml

                         

                        So far profiler shows no more blocking threads, but this is development machine (some max 10conn/sec). Will benchmark further.

                        Also open to any other suggestions.

                         

                        A