We are migrating from programmatic Hibernate session and transaction management to Spring Data JPA based declarative transaction. But when I log Spring and Hibernate transactions with log level debug I see different behavior - * when I am using programmatic hibernate session and transaction management, my finder and save method calls are executing under same session and transaction.
But when I am using spring @transactional annotation (with default propagation is REQUIRED), I am seeing the entityManager and transaction is opened and closed in each step (ie separately for the find and save method even though they are under one application level transaction). What I do not understand is as the find and save get called under one application level transaction (calling method has @Transactional - see code below), they should execute in that same instead of opening and closing their own (isn't it the behavior of default propagation level REQUIRED means)?
Here is the log from programmatic session management -
******************transformAndSaveAdjustments
2017-07-29 09:02:15,724 [transaction.spi.AbstractTransactionImpl 160 begin DEBUG]: begin
2017-07-29 09:02:15,725 [jdbc.internal.LogicalConnectionImpl 226 obtainConnection DEBUG]: Obtaining JDBC connection
2017-07-29 09:02:15,728 [jdbc.internal.LogicalConnectionImpl 232 obtainConnection DEBUG]: Obtained JDBC connection
2017-07-29 09:02:15,728 [internal.jdbc.JdbcTransaction 69 doBegin DEBUG]: initial autocommit status: true
2017-07-29 09:02:15,729 [internal.jdbc.JdbcTransaction 71 doBegin DEBUG]: disabling autocommit
2017-07-29 09:02:15,731 [org.hibernate.SQL 109 logStatement DEBUG]: select orderadjus0_.id as id1_31_, orderadjus0_.adjustment_reason as adjustme2_31_, orderadjus0_.adjustment_type as adjustme3_31_, orderadjus0_.approved_by as approved4_31_, orderadjus0_.created_by as created_5_31_, orderadjus0_.date_created as date_cre6_31_, orderadjus0_.last_updated as last_upd7_31_, orderadjus0_.note as note8_31_, orderadjus0_.order_id as order_id9_31_, orderadjus0_.source_of_error as source_10_31_, orderadjus0_.updated_by as updated11_31_, orderadjus0_.work_request as work_re12_31_ from order_adjustment orderadjus0_ where order_id=?
2017-07-29 09:02:15,735 [hibernate.loader.Loader 1486 getRow DEBUG]: Result row: EntityKey[commerce.order.OrderAdjustment#5855]
2017-07-29 09:02:15,744 [engine.internal.TwoPhaseLoad 160 doInitializeEntity DEBUG]: Resolving associations for [order.OrderAdjustment#5855]
2017-07-29 09:02:15,833 [engine.spi.ActionQueue 196 addResolvedEntityInsertAction DEBUG]: Executing identity-insert immediately
2017-07-29 09:02:15,833 [org.hibernate.SQL 109 logStatement DEBUG]: insert into order_adjustment (adjustment_reason, adjustment_type, approved_by, created_by, date_created, last_updated, note, order_id, source_of_error, updated_by, work_request) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
Hibernate: insert into order_adjustment (adjustment_reason, adjustment_type, approved_by, created_by, date_created, last_updated, note, order_id, source_of_error, updated_by, work_request) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2017-07-29 09:02:15,835 [hibernate.id.IdentifierGeneratorHelper 94 getGeneratedIdentity DEBUG]: Natively generated identity: 5867
2017-07-29 09:02:15,836 [transaction.spi.AbstractTransactionImpl 175 commit DEBUG]: committing
2017-07-29 09:02:15,836 [event.internal.AbstractFlushingEventListener 149 prepareEntityFlushes DEBUG]: Processing flush-time cascades
2017-07-29 09:02:15,836 [event.internal.AbstractFlushingEventListener 189 prepareCollectionFlushes DEBUG]: Dirty checking collections
2017-07-29 09:02:15,840 [event.internal.AbstractFlushingEventListener 123 logFlushResults DEBUG]: Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
2017-07-29 09:02:15,840 [event.internal.AbstractFlushingEventListener 130 logFlushResults DEBUG]: Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2017-07-29 09:02:15,841 [internal.util.EntityPrinter 114 toString DEBUG]: Listing entities:
2017-07-29 09:02:15,841 [internal.util.EntityPrinter 121 toString DEBUG]: commerce.order.OrderAdjustment{sourceOfError=test, lastUpdated=2017-07-29 13:02:15, note=test, adjustmentReason=test, dateCreated=2017-07-29 13:02:15, updatedBy=test, createdBy=test, orderId=12345, adjustmentType=ADJUSTMENT, approvedBy=test, id=5867, workRequest=test}
2017-07-29 09:02:15,848 [org.hibernate.SQL 109 logStatement DEBUG]: update order_adjustment set adjustment_reason=?, adjustment_type=?, approved_by=?, created_by=?, date_created=?, last_updated=?, note=?, order_id=?, source_of_error=?, updated_by=?, work_request=? where id=?
Hibernate: update order_adjustment set adjustment_reason=?, adjustment_type=?, approved_by=?, created_by=?, date_created=?, last_updated=?, note=?, order_id=?, source_of_error=?, updated_by=?, work_request=? where id=?
2017-07-29 09:02:15,875 [internal.jdbc.JdbcTransaction 113 doCommit DEBUG]: committed JDBC Connection
2017-07-29 09:02:15,876 [internal.jdbc.JdbcTransaction 126 releaseManagedConnection DEBUG]: re-enabling autocommit
2017-07-29 09:02:15,876 [jdbc.internal.JdbcCoordinatorImpl 201 close DEBUG]: HHH000420: Closing un-released batch
2017-07-29 09:02:15,877 [jdbc.internal.LogicalConnectionImpl 246 releaseConnection DEBUG]: Releasing JDBC connection
2017-07-29 09:02:15,878 [jdbc.internal.LogicalConnectionImpl 264 releaseConnection DEBUG]: Released JDBC connection
Below is the log using Spring Data JPA @Transactional
+++++++++++++++++saving using adjustmentPersister
2017-07-29 10:09:54,629 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findByOrderId]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; 'commerceDataApiTM'
2017-07-29 10:09:54,630 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Opened new EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@23e135ac] for JPA transaction
2017-07-29 10:09:54,630 [transaction.spi.AbstractTransactionImpl 160 begin DEBUG]: begin
2017-07-29 10:09:54,630 [jdbc.internal.LogicalConnectionImpl 226 obtainConnection DEBUG]: Obtaining JDBC connection
2017-07-29 10:09:54,631 [jdbc.internal.LogicalConnectionImpl 232 obtainConnection DEBUG]: Obtained JDBC connection
2017-07-29 10:09:54,631 [internal.jdbc.JdbcTransaction 69 doBegin DEBUG]: initial autocommit status: true
2017-07-29 10:09:54,631 [internal.jdbc.JdbcTransaction 71 doBegin DEBUG]: disabling autocommit
2017-07-29 10:09:54,632 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@4c01db8d]
2017-07-29 10:09:54,633 [jpa.criteria.CriteriaQueryImpl 327 interpret DEBUG]: Rendered criteria query -> select generatedAlias0 from Adjustment as generatedAlias0 where generatedAlias0.orderId=:param0
2017-07-29 10:09:54,633 [org.hibernate.SQL 109 logStatement DEBUG]: select adjustment0_.id as id1_3_, adjustment0_.adjustment_reason as adjustme2_3_, adjustment0_.adjustment_type as adjustme3_3_, adjustment0_.approved_by as approved4_3_, adjustment0_.created_by as created_5_3_, adjustment0_.date_created as date_cre6_3_, adjustment0_.last_updated as last_upd7_3_, adjustment0_.note as note8_3_, adjustment0_.order_id as order_id9_3_, adjustment0_.source_of_error as source_10_3_, adjustment0_.updated_by as updated11_3_, adjustment0_.work_request as work_re12_3_ from dbo.order_adjustment adjustment0_ where adjustment0_.order_id=?
2017-07-29 10:09:54,636 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Initiating transaction commit
2017-07-29 10:09:54,636 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Committing JPA transaction on EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@23e135ac]
2017-07-29 10:09:54,636 [transaction.spi.AbstractTransactionImpl 175 commit DEBUG]: committing
2017-07-29 10:09:54,637 [internal.jdbc.JdbcTransaction 113 doCommit DEBUG]: committed JDBC Connection
2017-07-29 10:09:54,637 [internal.jdbc.JdbcTransaction 126 releaseManagedConnection DEBUG]: re-enabling autocommit
2017-07-29 10:09:54,638 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Closing JPA EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@23e135ac] after transaction
2017-07-29 10:09:54,638 [orm.jpa.EntityManagerFactoryUtils 128 debug DEBUG]: Closing JPA EntityManager
2017-07-29 10:09:54,638 [jdbc.internal.LogicalConnectionImpl 246 releaseConnection DEBUG]: Releasing JDBC connection
2017-07-29 10:09:54,639 [jdbc.internal.LogicalConnectionImpl 264 releaseConnection DEBUG]: Released JDBC connection
2017-07-29 10:09:54,732 [core.support.TransactionalRepositoryProxyPostProcessor$CustomAnnotationTransactionAttributeSource 351 getTransactionAttribute DEBUG]: Adding transactional method 'save' with attribute: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2017-07-29 10:09:54,733 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2017-07-29 10:09:54,733 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Opened new EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@98f9e0b] for JPA transaction
2017-07-29 10:09:54,734 [transaction.spi.AbstractTransactionImpl 160 begin DEBUG]: begin
2017-07-29 10:09:54,734 [jdbc.internal.LogicalConnectionImpl 226 obtainConnection DEBUG]: Obtaining JDBC connection
2017-07-29 10:09:54,734 [jdbc.internal.LogicalConnectionImpl 232 obtainConnection DEBUG]: Obtained JDBC connection
2017-07-29 10:09:54,735 [internal.jdbc.JdbcTransaction 69 doBegin DEBUG]: initial autocommit status: true
2017-07-29 10:09:54,735 [internal.jdbc.JdbcTransaction 71 doBegin DEBUG]: disabling autocommit
2017-07-29 10:09:54,736 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@462d18ae]
2017-07-29 10:09:54,740 [engine.spi.ActionQueue 196 addResolvedEntityInsertAction DEBUG]: Executing identity-insert immediately
2017-07-29 10:09:54,741 [org.hibernate.SQL 109 logStatement DEBUG]: insert into dbo.order_adjustment (adjustment_reason, adjustment_type, approved_by, created_by, date_created, last_updated, note, order_id, source_of_error, updated_by, work_request) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) select scope_identity()
2017-07-29 10:09:54,744 [hibernate.id.IdentifierGeneratorHelper 94 getGeneratedIdentity DEBUG]: Natively generated identity: 5869
2017-07-29 10:09:54,744 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Initiating transaction commit
2017-07-29 10:09:54,745 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Committing JPA transaction on EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@98f9e0b]
2017-07-29 10:09:54,745 [transaction.spi.AbstractTransactionImpl 175 commit DEBUG]: committing
2017-07-29 10:09:54,745 [event.internal.AbstractFlushingEventListener 149 prepareEntityFlushes DEBUG]: Processing flush-time cascades
2017-07-29 10:09:54,745 [event.internal.AbstractFlushingEventListener 189 prepareCollectionFlushes DEBUG]: Dirty checking collections
2017-07-29 10:09:54,746 [event.internal.AbstractFlushingEventListener 123 logFlushResults DEBUG]: Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2017-07-29 10:09:54,746 [event.internal.AbstractFlushingEventListener 130 logFlushResults DEBUG]: Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2017-07-29 10:09:54,746 [internal.util.EntityPrinter 114 toString DEBUG]: Listing entities:
2017-07-29 10:09:54,747 [internal.util.EntityPrinter 121 toString DEBUG]: commerce.data.model.Adjustment{sourceOfError=SYSTEM, lastUpdated=2017-07-29 14:09:54, note=test, adjustmentReason=TAX_IN_ERROR, dateCreated=2017-07-29 14:09:54, updatedBy=soubhrad, createdBy=soubhrad, orderId=10679446, adjustmentType=ADJUSTMENT, approvedBy=test, id=5869, workRequest=test}
2017-07-29 10:09:54,751 [internal.jdbc.JdbcTransaction 113 doCommit DEBUG]: committed JDBC Connection
2017-07-29 10:09:54,752 [internal.jdbc.JdbcTransaction 126 releaseManagedConnection DEBUG]: re-enabling autocommit
2017-07-29 10:09:54,753 [orm.jpa.JpaTransactionManager 128 debug DEBUG]: Closing JPA EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@98f9e0b] after transaction
2017-07-29 10:09:54,753 [orm.jpa.EntityManagerFactoryUtils 128 debug DEBUG]: Closing JPA EntityManager
2017-07-29 10:09:54,754 [jdbc.internal.LogicalConnectionImpl 246 releaseConnection DEBUG]: Releasing JDBC connection
2017-07-29 10:09:54,754 [jdbc.internal.LogicalConnectionImpl 264 releaseConnection DEBUG]: Released JDBC connection
Here is the existing code- Hibernate based Dao -
public class AdjustmentDao extends BaseHibernateDao {
public List<Adjustment> findByOrderId(Integer orderId) {
try {
String queryString = "from OrderAdjustment o where order_id = :orderId ";
Query query = getSession().createQuery(queryString);
query.setParameter("orderId", orderId);
@SuppressWarnings("unchecked")
List<Adjustment> adjustments = query.list();
return adjustments;
} catch (HibernateException ex) {
String msg = "Exception finding Adjustment for order id:" + orderId;
LOG.error(msg, ex);
throw new CommerceRuntimeException(msg, ex);
}
}
public void saveAdjustments(Collection<Adjustment> adjustments) {
try {
save(adjustments);
} catch (HibernateException ex) {
Integer orderId = findOrderId(adjustments);
String msg = "Exception saving Adjustments for order id:" + orderId;
LOG.error(msg, ex);
throw new CommerceRuntimeException(msg, ex);
}
}
}
BaseHibernateDao -
public class BaseHibernateDao {
private Transaction transaction;
public void closeSession() {
HibernateSessionFactory.closeSession();
}
public void beginTransaction() {
if(this.transaction != null && this.transaction.isActive()) {
return;
}
if(getSession().getTransaction() != null &&
getSession().getTransaction().isActive()) {
setTransaction(getSession().getTransaction());
} else {
setTransaction(getSession().beginTransaction());
}
}
protected void save(Collection<? extends Object> transientInstances) throws HibernateException {
if (getTransaction() == null) {
throw new IllegalArgumentException("Transaction is null");
}
try {
for (Object transientInstance : transientInstances) {
getSession().save(transientInstance);
}
getTransaction().commit();
} catch (HibernateException ex) {
rollbackTransaction();
throw ex;
}
}
}
HIbernateSessionFactory-
public class HibernateSessionFactory {
/**
* Location of hibernate.cfg.xml file. Location should be on the classpath as Hibernate uses #resourceAsStream style
* lookup for its configuration file. The default classpath location of the hibernate config file is in the default
* package. Use #setConfigFile() to update the location of the configuration file for the current session.
*/
private static String CONFIG_FILE_LOCATION = "/config/hibernate.cfg.xml";
private static final ThreadLocal<Session> threadLocal = new ThreadLocal<Session>();
private static Configuration configuration = new Configuration();
private static SessionFactory sessionFactory;
private static String configFile = CONFIG_FILE_LOCATION;
private static final Logger LOG = LoggerFactory.getLogger(HibernateSessionFactory.class);
static {
try {
configuration.configure(configFile);
sessionFactory = configuration.buildSessionFactory();
} catch (Exception e) {
LOG.error("%%%% Error Creating SessionFactory %%%%", e);
}
}
private HibernateSessionFactory() {
}
/**
* Returns the ThreadLocal Session instance. Lazy initialize the <code>SessionFactory</code> if needed.
* @return Session
* @throws HibernateException
*/
public static Session getSession() throws HibernateException {
Session session = threadLocal.get();
if (session == null || !session.isOpen()) {
if (sessionFactory == null) {
rebuildSessionFactory();
}
session = (sessionFactory != null) ? sessionFactory.openSession() : null;
threadLocal.set(session);
}
return session;
}
/**
* Close the single hibernate session instance.
* @throws HibernateException
*/
public static void closeSession() throws HibernateException {
Session session = threadLocal.get();
threadLocal.set(null);
if (session != null) {
session.close();
}
}
}
And finally the use of DAO in application (its a grails app)- class OrderUpdateService {
static scope = "request"
AdjustmentDao adjustmentDao = new AdjustmentDao()
void transformAndSaveAdjustments(Integer orderId, def orderParams, User user) {
System.out.println("******************transformAndSaveAdjustments")
def adjustParams = orderParams.adjustments
if (adjustParams && !adjustParams.isEmpty()) {
adjustmentDao.getSession()
adjustmentDao.beginTransaction()
Collection<Adjustment> adjusts = adjustmentDao.findByOrderId(orderId)
ParametersToAdjustmentTransformer xform = new ParametersToAdjustmentTransformer()
Collection<Adjustment> adjustToSave = xform.transformAdjustmentData(adjusts, adjustParams, user, orderId)
adjustmentDao.saveAdjustments(adjustToSave)
adjustmentDao.closeSession()
}
}
Observe how the session and transactions are opened and find and save calls to DAO made with in same open session and transaction. This is what it is now (and may not be the best approach).
Now the new code Spring Data JPA @Transactional -
@Transactional(value="commerceDataApiTM", propagation=Propagation.REQUIRED)
public interface AdjustmentRepository extends JpaRepository<Adjustment, Integer> {
List<Adjustment> findByOrderId(Integer orderId);
}
@Component
@Transactional(value="commerceDataApiTM", propagation=Propagation.REQUIRED)
public class AdjustmentPersister {
private static final Logger LOG = LoggerFactory.getLogger(AdjustmentPersister.class);
@Autowired
private AdjustmentRepository adjustmentRepository;
public List<Adjustment> findByOrderId(Integer orderId) {
return adjustmentRepository.findByOrderId(orderId);
}
public void save(Adjustment adjustment) {
adjustmentRepository.save(adjustment);
}
public void save(List<Adjustment> adjustments) {
LOG.info("saving through new AdjustmentPersister.save()");
adjustmentRepository.save(adjustments);
}
}
And calling application code -
@Transactional("commerceDataApiTM")
void transformAndSaveAdjustments(Integer orderId, def orderParams, User user) {
System.out.println("+++++++++++++++++saving using adjustmentPersister")
def adjustParams = orderParams.adjustments
if (adjustParams && !adjustParams.isEmpty()) {
List<Adjustment> adjusts = adjustmentPersister.findByOrderId(orderId)
ParametersToAdjustmentTransformer xform = new ParametersToAdjustmentTransformer()
List<Adjustment> adjustToSave = xform.transformAdjustmentData(adjusts, adjustParams, user, orderId)
adjustmentPersister.save(adjustToSave)
}
}
