hibernate - Spring + Hibernate 事务需要 25 秒什么都不做

Question

我有一个使用 Spring + Hibernate 的 Java 应用程序。我有一个非常简单的事务，最近刚刚开始花费很长时间来执行(约 25 秒)，尽管它没有进行任何晦涩/复杂的查询，并且根据日志，这 25 秒花费在 Hiberante 的代码中。浏览器只是卡在那里等待完成......

事务是通过注释完成的，使用 org.springframework.orm.hibernate3.LocalSessionFactoryBean 作为 session 工厂，使用 org.springframework.orm.hibernate3.HibernateTransactionManager 作为事务管理器。

对于 Hibernate 的缓存，我使用的是 Memcached，但这应该不是问题，根据日志，至少它同时没有触及缓存......

我在这里提交相关的日志:

 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Found thread-bound Session [org.hibernate.impl.SessionImpl@a04a093] for Hibernate transaction
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Using transaction object [org.springframework.orm.hibernate3.HibernateTransactionManager$HibernateTransactionObject@35ca1808]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Creating new transaction with name [com.quebicoca.api.service.PaymentService.buy]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@a04a093]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Exposing Hibernate transaction as JDBC transaction [com.mysql.jdbc.JDBC4Connection@66efd0ce]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Bound value [org.springframework.jdbc.datasource.ConnectionHolder@a75b92e] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@1420ca8b] to thread [http-8080-12]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Initializing transaction synchronization
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionInterceptor] Getting transaction for [com.quebicoca.api.service.PaymentService.buy]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Retrieved value [org.springframework.orm.hibernate3.SessionHolder@3538ce1b] for key [org.hibernate.impl.SessionFactoryImpl@c4be179] bound to thread [http-8080-12]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Found thread-bound Session [org.hibernate.impl.SessionImpl@a04a093] for Hibernate transaction
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Retrieved value [org.springframework.jdbc.datasource.ConnectionHolder@a75b92e] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@1420ca8b] bound to thread [http-8080-12]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Using transaction object [org.springframework.orm.hibernate3.HibernateTransactionManager$HibernateTransactionObject@36d0805f]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Participating in existing transaction
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionInterceptor] Getting transaction for [com.quebicoca.api.service.PaymentService.buy]
 [DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Retrieved value [org.springframework.orm.hibernate3.SessionHolder@3538ce1b] for key [org.hibernate.impl.SessionFactoryImpl@c4be179] bound to thread [http-8080-12]
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|HashCodeKeyStrategy] Transformed key [UserOrder_holders] to hashCode [-1959252437]
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|HashCodeKeyStrategy] Final cache key: [org.hibernate.cache.UpdateTimestampsCache:0:-1959252437]
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|MemcachedCache] Memcache.set(org.hibernate.cache.UpdateTimestampsCache:0:-1959252437)
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|SpyMemcache] MemcachedClient.set(org.hibernate.cache.UpdateTimestampsCache:0:-1959252437)
 ...
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|DispatcherServlet] Successfully completed request
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|TransactionSynchronizationManager] Removed value [org.springframework.orm.hibernate3.SessionHolder@5862af29] for key [org.hibernate.impl.SessionFactoryImpl@c4be179] from thread [http-8080-25]
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|OpenSessionInViewFilter] Closing single Hibernate Session in OpenSessionInViewFilter
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|SessionFactoryUtils] Closing Hibernate Session
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|ExceptionTranslationFilter] Chain processed normally
 [DEBUG] [2010-10-09 @ 07:25:55] [http-8080-25|SecurityContextPersistenceFilter] SecurityContextHolder now cleared, as request processing completed
 [DEBUG] [2010-10-09 @ 07:25:56] [http-8080-12|TransactionSynchronizationManager] Retrieved value [org.springframework.orm.hibernate3.SessionHolder@3538ce1b] for key [org.hibernate.impl.SessionFactoryImpl@c4be179] bound to thread [http-8080-12]
 [DEBUG] [2010-10-09 @ 07:25:56] [http-8080-12|TransactionSynchronizationManager] Retrieved value [org.springframework.orm.hibernate3.SessionHolder@3538ce1b] for key [org.hibernate.impl.SessionFactoryImpl@c4be179] bound to thread [http-8080-12]
 [DEBUG] [2010-10-09 @ 07:25:56] [http-8080-12|HibernateTemplate] Found thread-bound Session for HibernateTemplate
 [DEBUG] [2010-10-09 @ 07:25:56] [http-8080-12|HashCodeKeyStrategy] Transformed key [UserOrder] to hashCode [-1966312925]
 [DEBUG] [2010-10-09 @ 07:25:56] [http-8080-12|HashCodeKeyStrategy] Final cache key: [org.hibernate.cache.UpdateTimestampsCache:0:-1966312925]

25 秒间隙之前记录的最后一件事是:

[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] 检索到键 [org.hibernate.SynchronizationManager] 的值 [org.springframework.orm.hibernate3.SessionHolder@3538ce1b]。 impl.SessionFactoryImpl@c4be179] 绑定(bind)到线程 [http-8080-12]

我是在此日志期间唯一登录的人，我关闭了除了我自己之外的所有人对 Tomcat 前面运行的 Apache 的访问。

欢迎任何想法。

编辑:

根据要求添加了我的订单类:

@Entity
@Table(name = "UserOrder")
@Cache(usage = CacheConcurrencyStrategy.READ_WRITE)
public class Order {

    @Id
    @GeneratedValue(strategy = GenerationType.AUTO)
    private Long id;

    @ManyToOne(optional = false)
    private Deal deal;
    @CollectionOfElements
    private Map<String, Integer> holders;
    @ManyToOne(optional = false)
    private User user;
    @org.hibernate.annotations.Type(type = "org.joda.time.contrib.hibernate.PersistentDateTime")
    @Column(nullable = false)
    private DateTime buyingDate;
    @Column(nullable = false)
    @Enumerated(EnumType.STRING)
    private OrderState state;
    private BigDecimal payedWithUserCredit;
    @Column(nullable = false)
    private int quantity;
    @Column(nullable = false)
    private String secret;

    private boolean mailSent;

    @Enumerated(EnumType.STRING)
    private PaymentMethod paymentMethod;
}

编辑2:

收到建议 Spy Memcached 可能有事可做后，我决定回到 EHCache。

情况变得更糟(1:16 悬挂)。日志:

 [DEBUG] [2010-10-13 @ 04:28:47] [http-8080-1|HibernateTransactionManager] Triggering beforeCommit synchronization
 [DEBUG] [2010-10-13 @ 04:28:47] [http-8080-1|HibernateTransactionManager] Triggering beforeCompletion synchronization
 [DEBUG] [2010-10-13 @ 04:28:47] [http-8080-1|HibernateTransactionManager] Initiating transaction commit
 [DEBUG] [2010-10-13 @ 04:28:47] [http-8080-1|HibernateTransactionManager] Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@20360e46]
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|HibernateTransactionManager] Triggering afterCommit synchronization
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|HibernateTransactionManager] Triggering afterCompletion synchronization
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|TransactionSynchronizationManager] Clearing transaction synchronization
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|TransactionSynchronizationManager] Removed value [org.springframework.jdbc.datasource.ConnectionHolder@30c2ea0b] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@614a616] from thread [http-8080-1]
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|HibernateTransactionManager] Not closing pre-bound Hibernate Session [org.hibernate.impl.SessionImpl@20360e46] after transaction
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|TransactionSynchronizationManager] Retrieved value [org.springframework.orm.hibernate3.SessionHolder@839c6c7] for key [org.hibernate.impl.SessionFactoryImpl@6fbae5f5] bound to thread [http-8080-1]
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|DriverManagerDataSource] Creating new JDBC DriverManager Connection to [jdbc:mysql://localhost/quebicoca]
 [DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|TransactionSynchronizationManager] Retrieved value [org.springframework.orm.hibernate3.SessionHolder@839c6c7] for key [org.hibernate.impl.SessionFactoryImpl@6fbae5f5] bound to thread [http-8080-1]

我完全迷失了......

Answer 1

明白了!

在执行此操作的 @Transactional 方法中，我会执行以下操作:

orderDAO.save(order);
user.addOrder(order);

因此订单将被保存，并添加到用户的订单集中。

调用保存时，已放置订单的插页，但未放置持有人的插页。

当退出该方法时，Hibernate 将检查 session 中的所有模型，以查看还需要保留哪些内容(这应该表明仅剩余 UserOrder_holder)。似乎需要永远尝试通过用户订单和相关交易(其中大多数在不同订单之间重复)来解决这个问题。我不是在谈论一个巨大的数据库，用于检索订单的查询只会从数据库返回 17 行......这太蹩脚了。

无论如何，让订单与交易的关系变得惰性解决了这个问题，至少目前如此，以后可能会随着更多订单而重新出现。