Remember that most database writes happen at transaction commit time.
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?
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.
You might try setting:
hibernate.show_sql = true
and checking what queries are issued at commit time.
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,
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.
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
you don't need extra logging to console or to file, as it will just additionaly slow down the system.
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.