Weird preformance degradation encounter on servlet-ejb-ejb call

[kristjan273]

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

[sfcoy]

Remember that most database writes happen at transaction commit time.

[kristjan273]

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?

[ctomc]

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

[sfcoy]

You might try setting:

     hibernate.show_sql = true

and checking what queries are issued at commit time.

[kristjan273]

@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

[sfcoy]

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.

[ctomc]

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

[kristjan273]

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