La transacción Spring + Hibernate demora 25 segundos sin hacer nada

Tengo una aplicación Java que usa Spring + Hibernate. Tengo una transacción bastante simple que hace poco que REALMENTE tardó en ejecutarse (~ 25 segundos), aunque no hace ninguna consulta oscura/compleja, y de acuerdo con el registro, esos 25 segundos se gastan dentro del código de Hiberante. El navegador simplemente se cuelga esperando hasta que se complete ...La transacción Spring + Hibernate demora 25 segundos sin hacer nada

La transacción se realiza mediante anotaciones, utilizando org.springframework.orm.hibernate3.LocalSessionFactoryBean como session factory y org.springframework.orm.hibernate3.HibernateTransactionManager como administrador de transacciones.

Por caché de Hibernate estoy usando Memcached, pero no debería ser un problema, de acuerdo con el registro de por lo menos no está tocando la memoria caché mientras tanto ....

aquí presento la pieza relevante del registro:

[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Found thread-bound Session [[email protected]] for Hibernate transaction 
[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Using transaction object [org.springframework.orm.hi[email protected]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 [[email protected]] 
[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Exposing Hibernate transaction as JDBC transaction [[email protected]] 
[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Bound value [[email protected]] for key [[email protected]ca8b] 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 [[email protected]] for key [[email protected]] bound to thread [http-8080-12] 
[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Found thread-bound Session [[email protected]] for Hibernate transaction 
[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|TransactionSynchronizationManager] Retrieved value [[email protected]] for key [[email protected]ca8b] bound to thread [http-8080-12] 
[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12|HibernateTransactionManager] Using transaction object [org.springframework.orm.hi[email protected]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 [[email protected]] for key [[email protected]] 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 [[email protected]] for key [[email protected]] 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 [[email protected]] for key [[email protected]] bound to thread [http-8080-12] 
[DEBUG] [2010-10-09 @ 07:25:56] [http-8080-12|TransactionSynchronizationManager] Retrieved value [[email protected]] for key [[email protected]] 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]

lo último registrado antes de la brecha de 25 segundos es:

[DEBUG] [2010-10-09 @ 07:25:30] [http-8080-12 | TransactionSynchronizationManager ] Valor obtenido [[email protected]] para la clave [org .hibernate.impl.SessionFactoryImpl @ c4be179] enlazado al hilo [http-8080-12]

Fui el único que inició sesión durante este registro, cerré el acceso para todos, excepto para mí, del Apache corriendo frente al Gato.

Cualquier idea es bienvenida.

EDIT:

Añadido mi clase de orden según solicitado:

@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; 
}

EDIT 2:

afeter sugerencias espía Memcached puede tener algo que ver decidí volver a EHCache.

Resultó ser aún peor (1:16 colgando). El registro:

[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 [[email protected]] 
[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 [[email protected]] for key [[email protected]616] from thread [http-8080-1] 
[DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|HibernateTransactionManager] Not closing pre-bound Hibernate Session [[email protected]] after transaction 
[DEBUG] [2010-10-13 @ 04:30:03] [http-8080-1|TransactionSynchronizationManager] Retrieved value [[email protected]] for key [[email protected]] 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 [[email protected]] for key [[email protected]] bound to thread [http-8080-1]

estoy perdido ... compeltely

Fuente

2010-10-12 Johnco

Debido al tiempo pasado de los mensajes de registro, estoy asumiendo (quizás incorrectamente) que la recuperación del titular de la sesión se haya completado en un tiempo razonable. ¿Es UserOrder una de sus clases, y si es así, cómo se ve? – Jeff

Jeff: No, ese mensaje de 'TransactionSynchronizationManager' significa el final de la recuperación. También Memcached puede ser un problema ya que 'HashCodeKeyStrategy' es una clase de hibernate-memcached. – axtavt

Agregué el código de Orden para Jeff. Espero que arroje algo de luz sobre el tema ... – Johnco

lo descubrió!

En el método @Transactional hacer esto me gustaría hacer algo como esto:

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

Así se ahorraría el orden, y se añade al conjunto de órdenes del usuario.

Cuando se llamó al guardar, se colocó el inserto para el pedido, pero no para el titular.

Al salir del método, Hibernate revisará todos los modelos en sesión para ver qué más necesita persistir (lo que debería indicar que solo queda el User_rder_holder). Parece que tomaría PARA SIEMPRE tratar de resolver esto con las Órdenes del Usuario y las Ofertas asociadas (la mayoría de las cuales se repiten entre diferentes Órdenes). Y no estoy hablando de una enorme base de datos, la consulta utilizada para recuperar los pedidos solo devolvería 17 filas de la base de datos ... Es lamentable.

De todos modos, haciendo que la relación del Pedido con el Deal lazy resolvió el problema, al menos por ahora, t puede resurgir más tarde con más pedidos.

Fuente

2010-10-13 05:29:50 Johnco

La transacción Spring + Hibernate demora 25 segundos sin hacer nada

Respuesta

Cuestiones relacionadas