在通过 wildfly 将实体持久化到 postgresql 期间挂起的多线程事务
Multithreading transactions hanging during persisting entity to postgresql via wildfly
我有一个像这样的 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 个实体持久化（插入）到 table 中存在问题。我试图在我的 public 书写方法和我的 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')"
每条建议对我都非常有帮助:)
I was trying to add @Transactional annotation on my public writing
method and on my api, but it doesn't work.
所有写操作都需要一个事务上下文，尤其是在使用 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");
}
org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
这一行对我来说有点无意义，但最近我发现了意义...我有一个项目结构 log4j.xml 在 WebContent/META-INF 文件夹，我使用的是 org.jboss.logging.Logger。不幸的是我没有得到任何错误，但是这个文件的位置是错误的。正如文档所说：
https://docs.jboss.org/process-guide/en/html/logging.html
The log4j configuration is loaded from the jboss server conf/log4j.xml
file.
我发现问题与 org.apache.log4j.ConsoleAppender 完全相关。删除它后，我现在对多线程没有任何问题，我不需要任何注释，因为 @TransactionalAttribute() 是根据需要设置的默认值。即使 EntityManager 不是线程安全的，也不需要使用 EntityManagerFactory。
看一下：
Log4j is hanging my application what am I doing wrong?
我收到了类似的异常，我怀疑只是达到了事务超时。
如果您再次查看日志消息，您会看到：
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.
我怀疑这只是在告诉我们交易超时已经到了，“交易收割者”现在将取消交易。由于这应该是从另一个线程发生的，因此有几个不相关的（并且非常混乱的错误消息）。
那么为什么这一切显然是由 log4j 引起的？
我认为这只是偶然：因为日志记录需要访问外部资源（控制台、文件系统等），线程在达到超时时“忙于”日志记录的机会实际上是相当高。并且当事务中止时，将捕获堆栈跟踪，并且 log4j 出现的机会并不低。
通过禁用 Console-Logger，您的性能有所提高，因此达到超时的频率会降低。
请注意，jboss 似乎不会取消已达到超时的事务 - 它只是将其标记为回滚：
我有一个像这样的 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 个实体持久化（插入）到 table 中存在问题。我试图在我的 public 书写方法和我的 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')"
每条建议对我都非常有帮助:)
I was trying to add @Transactional annotation on my public writing method and on my api, but it doesn't work.
所有写操作都需要一个事务上下文，尤其是在使用 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");
}
org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
这一行对我来说有点无意义，但最近我发现了意义...我有一个项目结构 log4j.xml 在 WebContent/META-INF 文件夹，我使用的是 org.jboss.logging.Logger。不幸的是我没有得到任何错误，但是这个文件的位置是错误的。正如文档所说： https://docs.jboss.org/process-guide/en/html/logging.html
The log4j configuration is loaded from the jboss server conf/log4j.xml file.
我发现问题与 org.apache.log4j.ConsoleAppender 完全相关。删除它后，我现在对多线程没有任何问题，我不需要任何注释，因为 @TransactionalAttribute() 是根据需要设置的默认值。即使 EntityManager 不是线程安全的，也不需要使用 EntityManagerFactory。
看一下： Log4j is hanging my application what am I doing wrong?
我收到了类似的异常，我怀疑只是达到了事务超时。
如果您再次查看日志消息，您会看到：
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.
我怀疑这只是在告诉我们交易超时已经到了，“交易收割者”现在将取消交易。由于这应该是从另一个线程发生的，因此有几个不相关的（并且非常混乱的错误消息）。
那么为什么这一切显然是由 log4j 引起的？
我认为这只是偶然：因为日志记录需要访问外部资源（控制台、文件系统等），线程在达到超时时“忙于”日志记录的机会实际上是相当高。并且当事务中止时，将捕获堆栈跟踪，并且 log4j 出现的机会并不低。
通过禁用 Console-Logger，您的性能有所提高，因此达到超时的频率会降低。
请注意，jboss 似乎不会取消已达到超时的事务 - 它只是将其标记为回滚：