Multithreading transactions hanging during persisting entity to postgresql via wildfly

Question

I've got a bean definition with an entityManager like this:

@Stateless
public class JPABean<T> {

    private static final Logger LOG = Logger.getLogger(JPABean.class);

    @PersistenceContext(unitName = "myPersistanceSettings")
    private EntityManager em;

    public void write(T o) {
        LOG.info("PERSISTING");
        em.persist(o);
        LOG.info("FLASHING");
        em.flush();
        LOG.info("SUCCESS");
    }

My persistance.xml

<persistence-unit name="eSystemJPA" transaction-type="JTA" >
    <provider>org.hibernate.ejb.HibernatePersistence</provider>
    <jta-data-source>java:jboss/datasources/myDS</jta-data-source>
    <properties>
        <property name="hibernate.show_sql" value="true" />
        <property name="hibernate.hbm2ddl.auto" value="validate" />
        <property name="hibernate.dialect" value="org.hibernate.dialect.PostgreSQLDialect"/>
        <property name="hibernate.transaction.jta.platform" value="org.hibernate.service.jta.platform.internal.JBossAppServerJtaPlatform" />
    </properties>
</persistence-unit>

My api:

@Path("activityAPI")
public class ActivityAPI {

    private static final Logger log = Logger.getLogger(ActivityAPI.class);

    @EJB
    private JPABean<ActivityLogEntry> activityJpa;

    @POST
    @Consumes(MediaType.APPLICATION_JSON)
    @Produces(MediaType.APPLICATION_JSON)
    public Response reportActivity(@Context HttpServletRequest hsr, final ActivityAPIRequest body) { ...

My standalone.xml with datasource:

    <datasource jta="true" jndi-name="java:jboss/datasources/myDS" pool-name="PostgrePool" enabled="true" spy="true" use-ccm="false">
            <connection-url>jdbc:postgresql://localhost/postgres</connection-url>
            <driver>postgres</driver>
            <pool>
                <min-pool-size>10</min-pool-size>
                <max-pool-size>100</max-pool-size>
                <prefill>true</prefill>
            </pool>
            <security>
                <user-name>postgres</user-name>
                <password>postgres</password>
            </security>
            <validation>
                <validate-on-match>false</validate-on-match>
                <background-validation>false</background-validation>
            </validation>
            <statement>
                <share-prepared-statements>false</share-prepared-statements>
            </statement>
        </datasource>

And i'm receiving:

2015-03-11 17:48:39,945 INFO    [JPABean.write]: PERSISTING
2015-03-11 17:48:39,946 INFO    [AbstractLoggingWriter.write]: INFO   [JPABean.write]: PERSISTING
2015-03-11 17:48:39,946 DEBUG   [TransactionCoordinatorImpl.attemptToRegisterJtaSync]: Skipping JTA sync registration due to auto join checking
2015-03-11 17:48:39,946 INFO    [AbstractLoggingWriter.write]: DEBUG  [TransactionCoordinatorImpl.attemptToRegisterJtaSync]: Skipping JTA sync registration due to auto join checking
2015-03-11 17:48:39,947 DEBUG   [TransactionCoordinatorImpl.attemptToRegisterJtaSync]: successfully registered Synchronization
2015-03-11 17:48:39,947 INFO    [AbstractLoggingWriter.write]: DEBUG  [TransactionCoordinatorImpl.attemptToRegisterJtaSync]: successfully registered Synchronization
2015-03-11 17:48:39,947 DEBUG   [AbstractEntityManagerImpl.joinTransaction]: Looking for a JTA transaction to join
2015-03-11 17:48:39,947 INFO    [AbstractLoggingWriter.write]: DEBUG  [AbstractEntityManagerImpl.joinTransaction]: Looking for a JTA transaction to join
2015-03-11 17:48:39,948 INFO    [AbstractLoggingWriter.write]: Hibernate: select nextval ('hibernate_sequence')
2015-03-11 17:48:39,949 DEBUG   [LogicalConnectionImpl.obtainConnection]: Obtaining JDBC connection
2015-03-11 17:48:39,949 INFO    [AbstractLoggingWriter.write]: DEBUG  [LogicalConnectionImpl.obtainConnection]: Obtaining JDBC connection
2015-03-11 17:48:39,950 DEBUG   [LogicalConnectionImpl.obtainConnection]: Obtained JDBC connection
2015-03-11 17:48:39,950 INFO    [AbstractLoggingWriter.write]: DEBUG  [LogicalConnectionImpl.obtainConnection]: Obtained JDBC connection
2015-03-11 17:48:39,952 DEBUG   [LogicalConnectionImpl.releaseConnection]: Releasing JDBC connection
2015-03-11 17:48:39,952 INFO    [AbstractLoggingWriter.write]: DEBUG  [LogicalConnectionImpl.releaseConnection]: Releasing JDBC connection
2015-03-11 17:48:39,953 DEBUG   [LogicalConnectionImpl.releaseConnection]: Released JDBC connection
2015-03-11 17:48:39,953 INFO    [AbstractLoggingWriter.write]: DEBUG  [LogicalConnectionImpl.releaseConnection]: Released JDBC connection
2015-03-11 17:48:39,954 INFO    [JPABean.write]: FLASHING
2015-03-11 17:48:39,955 INFO    [AbstractLoggingWriter.write]: INFO   [JPABean.write]: FLASHING
2015-03-11 17:48:39,957 INFO    [AbstractLoggingWriter.write]: DEBUG  [ActivityAPI.reportActivity]: POST Received PUT reportActivity
2015-03-11 17:48:39,957 DEBUG   [EntityPrinter.toString]: Listing entities:
2015-03-11 17:48:39,957 INFO    [AbstractLoggingWriter.write]: DEBUG  [EntityPrinter.toString]: Listing entities:
2015-03-11 17:48:39,958 DEBUG   [EntityPrinter.toString]: ActivityLogEntry{... body ...}
2015-03-11 17:48:39,958 INFO    [AbstractLoggingWriter.write]: DEBUG  [EntityPrinter.toString]: ActivityLogEntry{... body ...}
2015-03-11 17:48:39,959 INFO    [JPABean.write]: PERSISTING
2015-03-11 17:48:39,959 INFO    [AbstractLoggingWriter.write]: INFO   [JPABean.write]: PERSISTING
2015-03-11 17:48:39,962 INFO    [AbstractLoggingWriter.write]: Hibernate: insert into activity_log_entry (all columns) values (?, ?, ?, ?, ?, ?, ?, ?, ?)

So in fact there is a problem with persisting (inserting) 2 entities into a table. I was trying to add @Transactional annotation on my public writing method and on my api, but it doesn't work. I was trying also with @TransactionAttribute(TransactionAttributeType.REQUIRED), but it's still the same. Also using EntityManagerFactory to create entityManager doesn't work (documentation says that entityManager is not thread-safe, but EntityManagerFactory is thread-safe). I'm using:

postgressql - 9.3 jboss-ejb-api_3.2_spec jboss-servlet-api_3.1_spec resteasy-jaxrs hibernate-entitymanager hibernate-validator driver postresql>9.3-1102-jdbc41 wildfly 8.2 or wildfly 8.0

logs from hibernate:

2015-03-11 17:53:39,947 WARN    [SynchronizationCallbackCoordinatorTrackingImpl.afterCompletion]: HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]

Trace from wildfly

17:53:39,944 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:62455507:550071b3:35 in state  RUN
    17:53:39,945 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000001:62455507:550071b3:35 invoked while multiple threads active within it.
    17:53:39,946 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000001:62455507:550071b3:35 aborting with 1 threads active!
    17:53:39,957 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:62455507:550071b3:3b in state  RUN
    17:53:40,445 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:62455507:550071b3:35 in state  CANCEL
    17:53:40,446 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
    org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
    org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:79)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    org.jboss.logmanager.Logger.logRaw(Logger.java:721)
    org.jboss.logmanager.Logger.log(Logger.java:672)
    org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:50)
    org.jboss.logging.Logger.logf(Logger.java:2096)
    org.hibernate.internal.CoreMessageLogger_$logger.rollbackFromBackgroundThread(CoreMessageLogger_$logger.java:1032)
    org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorTrackingImpl.afterCompletion(SynchronizationCallbackCoordinatorTrackingImpl.java:85)
    org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.afterCompletion(RegisteredSynchronization.java:56)
    com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
    com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:532)
    com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:463)
    com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:118)
    com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
    com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:377)
    com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)

    17:53:40,457 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:62455507:550071b3:3b in state  SCHEDULE_CANCEL
    17:53:40,947 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:62455507:550071b3:35 in state  CANCEL_INTERRUPTED
    17:53:40,948 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 0,5,main] not responding to interrupt when cancelling TX 0:ffff7f000001:62455507:550071b3:35 -- worker marked as zombie and TX scheduled for mark-as-rollback
    17:53:40,949 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012110: TransactionReaper::check successfuly marked TX 0:ffff7f000001:62455507:550071b3:35 as rollback only
    17:53:40,948 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 1) ARJUNA012095: Abort of action id 0:ffff7f000001:62455507:550071b3:3b invoked while multiple threads active within it.
    17:53:40,949 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 1) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000001:62455507:550071b3:3b aborting with 1 threads active!
    17:53:40,949 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 1) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 1,5,main] successfully canceled TX 0:ffff7f000001:62455507:550071b3:3b

I also saw that my transcations are in idle state in postgressql:

"idle in transaction";"select nextval ('hibernate_sequence')"
"idle in transaction";"select nextval ('hibernate_sequence')"

Every suggestion will be extremely helpful for me :)

Marcin Erbel · Accepted Answer · 2017-12-19T07:11:59.647

2

org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)

This line was a little bit meaningless for me, but recently I find out the meaning... I had a structure of my project with log4j.xml inside WebContent/META-INF folder and i was using org.jboss.logging.Logger. Unfortunately i didn't get any error but the location of this file was wrong. As documentation says: https://docs.jboss.org/process-guide/en/html/logging.html

The log4j configuration is loaded from the jboss server conf/log4j.xml file.

I recognize that problem is connected exactly with org.apache.log4j.ConsoleAppender. After removed it I don't have any problem with multithreading now and I don't need any annotation cause @TransactionalAttribute() is on default set as required. Also there is no need to use EntityManagerFactory even if EntityManager is not thread-safe.

Take a look on that: Log4j is hanging my application what am I doing wrong?

edited Dec 19 '17 at 07:11

answered Mar 16 '15 at 15:34

Marcin Erbel

1,597
6
32
51

1

The instructions at (https://docs.jboss.org/process-guide/en/html/logging.html) predate JBossAS 7.x and WildFly by many years and are no longer relevant. – Steve C Mar 21 '15 at 12:03
2

I suspect that you have encountered a log4j deadlock problem similar to that described at (http://java.dzone.com/articles/log4j-thread-deadlock-case). – Steve C Mar 21 '15 at 12:11
Even I had faced a similar deadlock on wildfly due to log4j. Identified it using jvisualvm and fixed it by using Async Appender in log4j configuration. – jithin iyyani Mar 21 '15 at 16:33

score 1 · Answer 2 · answered Aug 05 '21 at 06:20

I received a similar exception and my suspicion is that simply the transaction timeout has been reached.

If you look at the log messages again, you will see that:

17:53:39,944 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:62455507:550071b3:35 in state RUN 17:53:39,945 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000001:62455507:550071b3:35 invoked while multiple threads active within it.

I suspect that this is simply telling us that the transaction timeout has been reached and the "Transaction Reaper" will cancel the transaction now. As this is supposedly happening from another thread, there are several unrelated (and quite confusing error messages).

So why is all of this apparently caused by log4j?

I think this is just by chance: Because logging requires access to external resources (Console, File System, ...) the chance of the thread being "busy" with logging at the time it reaches the timeout is actually rather high. And when the transaction is aborted, a stack trace will be caught and the chance of log4j appearing there is not that low.

By disabling the Console-Logger, you have improved performance a bit, so the timeout will be reached less often.

Note that jboss does not seem to cancel a transaction which has reached a timeout - it just marks it for rollback: https://stackoverflow.com/a/5680952/232175

score 0 · Answer 3 · answered Mar 15 '15 at 15:27

0

I was trying to add @Transactional annotation on my public writing method and on my api, but it doesn't work.

All write operations require a Transactional context, especially in a JTA environment, where aggressive connection release are employed. You need to add:

@TransactionAttribute(TransactionAttributeType.REQUIRED)

to your write method:

@TransactionAttribute(TransactionAttributeType.REQUIRED)
public void write(T o) {
    LOG.info("PERSISTING");
    em.persist(o);
    LOG.info("FLASHING");
    em.flush();
    LOG.info("SUCCESS");
}

answered Mar 15 '15 at 15:27

Vlad Mihalcea

142,745
71
566
911

I was trying to do that, but unfortunatelly it doesn't work. Still have the same problem. – Marcin Erbel Mar 15 '15 at 16:14
Any exception when you try adding the transaction annotation? – Vlad Mihalcea Mar 15 '15 at 16:39
Unfortunately i didn't saw any difference between using "@Transactional" and "@TransactionAttribute". Still the same, thread stops on inserting to DB or on generating sequence. After a few minutes i see errors from arjuna and finally i need to kill wildfly. When im debugging (so every thread/request is stopping on the beggining) and im running every thread separately everything is fine... – Marcin Erbel Mar 15 '15 at 19:13
Make sure you use the [Postgres XA](https://access.redhat.com/documentation/en-US/JBoss_Enterprise_Application_Platform/6/html/Administration_and_Configuration_Guide/Example_PostgreSQL_XA_Datasource.html) DataSource. – Vlad Mihalcea Mar 15 '15 at 19:39
For sure Im using org.postgresql.Driver. I will try to change it to XA DataSource and I will let you know! – Marcin Erbel Mar 15 '15 at 19:52
1

When you're using JTA, you need XA compliant DataSources. A non-XA might fall back to one-phase commit and LastResourceCommit optimization, but probably that's not properly supported. – Vlad Mihalcea Mar 15 '15 at 19:56
It's not that two-phase commit within a single JBoss AS instance is handled by the local data source? I was thinking that XA is mainly for clustering – Marcin Erbel Mar 15 '15 at 20:01
"(...) If you app only uses a single datasource, use local-tx If your app uses two datasources, use xa-datasource(..)" https://developer.jboss.org/thread/151380?start=15&tstart=0 – Marcin Erbel Mar 15 '15 at 20:09
1

XA is used for distributed transactions and that's what JTA does. Resource local transactions use a single DS only and the transaction is coordinated through the JDBC Connection commit/rollback. – Vlad Mihalcea Mar 15 '15 at 20:10
I used XA-datasource, and last log is still: 10:14:21,582 DEBUG [org.hibernate.SQL] (default task-14) select firstclien0_.clientCustomerId as clientCu1_4_0_, firstclien0_.clientLogin as clientLo2_4_0_, firstclien0_.date as date3_4_0_ from first_client_login_entry firstclien0_ where firstclien0_.clientCustomerId=? but now, i don't see any idle in transactions on database – Marcin Erbel Mar 16 '15 at 09:15
1

The writeTo method is on an EJB. @TransactionAttribute(TransactionAttributeType.REQUIRED) is the default behaviour, so the annotation is redundant. – Steve C Mar 21 '15 at 12:00

Multithreading transactions hanging during persisting entity to postgresql via wildfly

3 Answers3

Linked