通过wildfly将实体持久化到postgresql期间挂起的多线程事务

Posted 2023-02-27

技术标签:

【中文标题】通过wildfly将实体持久化到postgresql期间挂起的多线程事务【英文标题】：Multithreading transactions hanging during persisting entity to postgresql via wildfly 【发布时间】：2015-05-13 14:51:27 【问题描述】：

我有一个像这样的 entityManager 的 bean 定义：

@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");

我的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>

我的 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)  ...

我的带有数据源的standalone.xml：

    <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>

我收到了：

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 (?, ?, ?, ?, ?, ?, ?, ?, ?)

所以实际上将 2 个实体持久化（插入）到一个表中是有问题的。我试图在我的公共写作方法和我的 api 上添加 @Transactional 注释，但它不起作用。我也在尝试使用@TransactionAttribute(TransactionAttributeType.REQUIRED)，但它仍然是一样的。也使用 EntityManagerFactory 创建 entityManager 不起作用（文档说 entityManager 不是线程安全的，但 EntityManagerFactory 是线程安全的）。我正在使用：

postgressql - 9.3 jboss-ejb-api_3.2_spec jboss-servlet-api_3.1_spec resteasy jaxrs 休眠实体管理器休眠验证器驱动 postresql>9.3-1102-jdbc41 Wildfly 8.2 或 Wildfly 8.0

来自休眠的日志：

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]

野蝇的踪迹

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

我还看到我的事务在 postgressql 中处于空闲状态：

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

每一个建议都会对我非常有帮助:)

【问题讨论】：

【参考方案1】：

我收到了类似的异常，我怀疑只是已经达到事务超时。

如果您再次查看日志消息，您会看到：

17:53:39,944 WARN [com.arjuna.ats.arjuna]（交易收割者） ARJUNA012117: TransactionReaper::检查 TX 超时 0:ffff7f000001:62455507:550071b3:35 处于运行状态 17:53:39,945 WARN [com.arjuna.ats.arjuna]（交易收割工人 0）ARJUNA012095： Abort of action id 0:ffff7f000001:62455507:550071b3:35 在其中多个线程处于活动状态时被调用。

我怀疑这只是告诉我们已经达到交易超时，“交易收割者”现在将取消交易。由于这应该是从另一个线程发生的，因此有几个不相关的（并且非常混乱的错误消息）。

那么为什么这一切显然是由 log4j 引起的呢？

我认为这只是偶然：因为日志记录需要访问外部资源（控制台、文件系统……），线程在达到超时时“忙”于日志记录的机会实际上相当高.并且当事务中止时，会捕获堆栈跟踪，并且 log4j 出现在那里的机会并没有那么低。

通过禁用 Console-Logger，您的性能有所提高，因此超时会减少。

请注意，jboss 似乎不会取消已达到超时的事务 - 它只是将其标记为回滚：https://***.com/a/5680952/232175

【讨论】：

【参考方案2】：

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

这行对我来说有点无意义，但最近我发现了意义......我在 WebContent/META-INF 文件夹中有一个带有 log4j.xml 的项目结构，我正在使用 org.jboss.logging.Logger。不幸的是，我没有收到任何错误，但这个文件的位置是错误的。正如文件所说： https://docs.jboss.org/process-guide/en/html/logging.html

log4j 配置是从 jboss 服务器加载的 conf/log4j.xml 文件。

我知道这个问题与 org.apache.log4j.ConsoleAppender 完全相关。删除它后，我现在对多线程没有任何问题，我不需要任何注释，因为 @TransactionalAttribute() 是按要求设置的默认值。即使 EntityManager 不是线程安全的，也不需要使用 EntityManagerFactory。

看一下： Log4j is hanging my application what am I doing wrong?

【讨论】：

(docs.jboss.org/process-guide/en/html/logging.html) 上的说明比 JBossAS 7.x 和 WildFly 早了很多年，不再相关。我怀疑您遇到了类似于 (java.dzone.com/articles/log4j-thread-deadlock-case) 中描述的 log4j 死锁问题。由于 log4j，即使我在 Wildfly 上也遇到过类似的死锁。使用 jvisualvm 识别它并在 log4j 配置中使用 Async Appender 修复它。【参考方案3】：

我试图在我的公开写作中添加@Transactional 注释方法和我的api，但它不起作用。

所有写操作都需要事务上下文，尤其是在使用aggressive connection release 的JTA 环境中。您需要添加：

@TransactionAttribute(TransactionAttributeType.REQUIRED)

到您的write 方法：

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

【讨论】：

我试图这样做，但不幸的是它不起作用。还是有同样的问题。尝试添加事务注解有异常吗？当您使用 JTA 时，您需要符合 XA 的数据源。非 XA 可能会退回到单阶段提交和 LastResourceCommit 优化，但可能没有得到适当的支持。 XA 用于分布式事务，这就是 JTA 所做的。资源本地事务仅使用单个 DS，事务通过 JDBC 连接提交/回滚进行协调。 writeTo 方法在 EJB 上。 @TransactionAttribute(TransactionAttributeType.REQUIRED) 是默认行为，所以注解是多余的。

以上是关于通过wildfly将实体持久化到postgresql期间挂起的多线程事务的主要内容，如果未能解决你的问题，请参考以下文章

如何在 Wildfly 21 上配置 Jakarta 持久性

Wildfly 中有多个持久性单元？

Wildfly/JBOSS 持久性错误 MSC000001：无法启动服务 jboss.persistenceunit

当persistence.xml存在时，为啥持久性单元命名为null

Hibernate：将现有子实体添加到具有 OneToMany 双向关系的新实体并将其持久化（“分离的实体传递给持久化”）

我应该将 DTO 映射到客户端和服务器端的域实体/从域实体映射吗？