Как работает атрибут тайм-аута @Transactional с разным распространением

Question

Я запутался с поведением атрибута тайм-аута @Transactional

У меня следующая последовательность

Main -> 
UserExecutionServiceImpl.executeRecordInvoice ->
ProcessInvoiceServiceImpl.recordInvoice ->
WarehouseServiceImpl.checkStockAvailability

Для принудительного тайм-аута отката установлено значение 0.

Если executeRecordInvoice имеет @Transactional(timeout=0) исключение выбрасывается и там останавливаются все. Имеет смысл

Если executeRecordInvoice имеет @Transactional и запись Invoice имеет @Transactional(timeout=0) исключение не выбрасывается. Практически значение таймаута было проигнорировано.

Я мог бы предположить, потому что транзакция действительно начинается с executeRecordInvoice и, кроме того, потому что оба метода по умолчанию Propagation.Required, это означает, что вторая (recordInvoice) считается внутри первой (executeRecordInvoice) уже существующей транзакции, которая выполняется

Более того, я провел два простых эксперимента:

1. Если executeRecordInvoice имеет @Transactional и запись Invoice имеет @Transactional(propagation.Propagation.REQUIRES_NEW, timeout=0) исключение брошено. Теперь работает, потому что новая запись начинается в recordInvoice и, следовательно, время ожидания считается.

2. Звоните из Главного класса напрямую ProcessInvoiceServiceImpl.recordInvoice, это с @Transactional(propagation.Propagation.REQUIRED, timeout=0) или с @Transactional(propagation.Propagation.REQUIRES_NEW, timeout=0)опять таймаут считается.

До здесь у меня все хорошо, и все имеет смысл. Но применение 1 и 2 для WarehouseServiceImpl.checkStockAvailability не работает:

1. Если executeRecordInvoice и recordInvoice имеют @Transactional (следовательно, оба распространяются по умолчанию) и checkStockAvailability имеет @Transactional(propagation.Propagation.REQUIRES_NEW, timeout=0), Исключение не брошено!

2. Звоните из Главного класса напрямую WarehouseServiceImpl.checkStockAvailability, это с @Transactional(propagation.Propagation.REQUIRED, timeout=0) или с @Transactional(propagation.Propagation.REQUIRES_NEW, timeout=0)опять таймаут не считается.

Объявление класса

@Service
@Transactional
@Scope("prototype")
public class WarehouseServiceImpl implements WarehouseService {

    // Unique method implementation
    @Transactional(propagation = Propagation.REQUIRES_NEW, timeout=0)
    public boolean checkStockAvailability(Product product, BigDecimal quantity) {

        ...

    return true;

    }
}

Любая идея или предложение приветствуется.

Spring Framework 4.0.5

Спасибо.

После того, как сделать предложение Андрея, у меня есть следующее:

@Transactional
@Scope("prototype")
@Service("processInvoiceService")
public class ProcessInvoiceServiceImpl implements ProcessInvoiceService {

    @Override
    @Transactional(propagation = Propagation.REQUIRES_NEW, timeout=0)
    public void recordInvoice(InvoiceHeader invoiceHeader) {

И в классе MainTest

ProcessInvoiceService processInvoiceService = context.getBean(ProcessInvoiceService.class);

        try{
            processInvoiceService.recordInvoice(invoiceHeader03);
        }
        catch(Exception e){
            logger.error("ERROR ALFA: {}", e.getMessage());
        }

С показывает Консоль, часть в выводе результата

Creating instance of bean 'processInvoiceService'
20:16:57,320 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'productService'
20:16:57,320 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'invoiceHeaderService'
20:16:57,320 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'invoiceDetailService'
20:16:57,321 DEBUG ctory.support.DefaultListableBeanFactory: 449 - Creating instance of bean 'warehouseServiceImpl'
20:16:57,321 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
20:16:57,321 DEBUG xy.InfrastructureAdvisorAutoProxyCreator: 593 - Creating implicit proxy for bean 'warehouseServiceImpl' with 0 common interceptors and 1 specific interceptors
20:16:57,321 DEBUG amework.aop.framework.JdkDynamicAopProxy: 117 - Creating JDK dynamic proxy: target source is SingletonTargetSource for target object [com.manuel.jordan.model.service.support.impl.WarehouseServiceImpl@7b4c50bc]
20:16:57,321 DEBUG ctory.support.DefaultListableBeanFactory: 477 - Finished creating instance of bean 'warehouseServiceImpl'
20:16:57,322  INFO e.process.impl.ProcessInvoiceServiceImpl:  46 - ProcessInvoiceServiceImpl arg constructor
20:16:57,322 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
20:16:57,322 DEBUG xy.InfrastructureAdvisorAutoProxyCreator: 593 - Creating implicit proxy for bean 'processInvoiceService' with 0 common interceptors and 1 specific interceptors
20:16:57,322 DEBUG amework.aop.framework.JdkDynamicAopProxy: 117 - Creating JDK dynamic proxy: target source is SingletonTargetSource for target object [com.manuel.jordan.model.service.process.impl.ProcessInvoiceServiceImpl@5884a914]
20:16:57,322 DEBUG ctory.support.DefaultListableBeanFactory: 477 - Finished creating instance of bean 'processInvoiceService'
20:16:57,322 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
20:16:57,322 DEBUG .datasource.DataSourceTransactionManager: 367 - Creating new transaction with name [com.manuel.jordan.model.service.process.impl.ProcessInvoiceServiceImpl.recordInvoice]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,timeout_0; ''
20:16:57,322 DEBUG k.jdbc.datasource.SimpleDriverDataSource: 138 - Creating new JDBC Driver Connection to [jdbc:hsqldb:mem:testdb]
20:16:57,323 DEBUG .datasource.DataSourceTransactionManager: 206 - Acquired Connection [org.hsqldb.jdbc.JDBCConnection@50378a4] for JDBC transaction
20:16:57,323 DEBUG .datasource.DataSourceTransactionManager: 223 - Switching JDBC Connection [org.hsqldb.jdbc.JDBCConnection@50378a4] to manual commit
20:16:57,323  INFO e.process.impl.ProcessInvoiceServiceImpl:  59 - ProcessInvoiceServiceImpl recordInvoice - start
20:16:57,323 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
20:16:57,323 DEBUG .datasource.DataSourceTransactionManager: 472 - Participating in existing transaction
20:16:57,323 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
20:16:57,323 DEBUG .datasource.DataSourceTransactionManager: 472 - Participating in existing transaction
20:16:57,324 DEBUG g.springframework.jdbc.core.JdbcTemplate: 908 - Executing prepared SQL update
20:16:57,324 DEBUG g.springframework.jdbc.core.JdbcTemplate: 627 - Executing prepared SQL statement [INSERT INTO invoiceheader(id, number, date, total) VALUES(?, ?, ?, ?)]
20:16:57,324 DEBUG .datasource.DataSourceTransactionManager: 854 - Participating transaction failed - marking existing transaction as rollback-only
20:16:57,324 DEBUG .datasource.DataSourceTransactionManager: 295 - Setting JDBC transaction [org.hsqldb.jdbc.JDBCConnection@50378a4] rollback-only
20:16:57,324 DEBUG .datasource.DataSourceTransactionManager: 854 - Participating transaction failed - marking existing transaction as rollback-only
20:16:57,325 DEBUG .datasource.DataSourceTransactionManager: 295 - Setting JDBC transaction [org.hsqldb.jdbc.JDBCConnection@50378a4] rollback-only
20:16:57,325 DEBUG .datasource.DataSourceTransactionManager: 847 - Initiating transaction rollback
20:16:57,325 DEBUG .datasource.DataSourceTransactionManager: 281 - Rolling back JDBC transaction on Connection [org.hsqldb.jdbc.JDBCConnection@50378a4]
20:16:57,325 DEBUG .datasource.DataSourceTransactionManager: 324 - Releasing JDBC Connection [org.hsqldb.jdbc.JDBCConnection@50378a4] after transaction
20:16:57,325 DEBUG ramework.jdbc.datasource.DataSourceUtils: 327 - Returning JDBC Connection to DataSource
20:16:57,325 ERROR          com.manuel.jordan.main.MainTest:  93 - ERROR ALFA: Transaction timed out: deadline was Mon Jun 30 20:16:57 PET 2014
20:16:57,325 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'

появляется сообщение об ошибке, как ожидается..

Теперь для другого класса

@Service
@Transactional
@Scope("prototype")
public class WarehouseServiceImpl implements WarehouseService {

    private static final Logger logger = LoggerFactory.getLogger(WarehouseServiceImpl.class);

    @Override
    @Transactional(propagation = Propagation.REQUIRES_NEW, timeout=0)
    public boolean checkStockAvailability(Product product, BigDecimal quantity) {

И в классе MainTest

WarehouseService warehouseService = context.getBean(WarehouseService.class);

        try{
            logger.info("Pre");
            boolean result = warehouseService.checkStockAvailability(product01, BigDecimal.ZERO);
            logger.info("result: {}", result);
            logger.info("Post");
        }
        catch(Exception e){
            logger.error("ERROR BETA: {}", e.getMessage());
        }

С показывает Консоль, часть в выводе результата

20:16:57,337 DEBUG ctory.support.DefaultListableBeanFactory: 449 - Creating instance of bean 'warehouseServiceImpl'
20:16:57,337 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
20:16:57,338 DEBUG xy.InfrastructureAdvisorAutoProxyCreator: 593 - Creating implicit proxy for bean 'warehouseServiceImpl' with 0 common interceptors and 1 specific interceptors
20:16:57,338 DEBUG amework.aop.framework.JdkDynamicAopProxy: 117 - Creating JDK dynamic proxy: target source is SingletonTargetSource for target object [com.manuel.jordan.model.service.support.impl.WarehouseServiceImpl@23f5b5dc]
20:16:57,338 DEBUG ctory.support.DefaultListableBeanFactory: 477 - Finished creating instance of bean 'warehouseServiceImpl'
20:16:57,338  INFO          com.manuel.jordan.main.MainTest: 102 - Pre
20:16:57,338 DEBUG ion.AnnotationTransactionAttributeSource: 108 - Adding transactional method 'WarehouseServiceImpl.checkStockAvailability' with attribute: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,timeout_0; ''
20:16:57,338 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
20:16:57,339 DEBUG .datasource.DataSourceTransactionManager: 367 - Creating new transaction with name [com.manuel.jordan.model.service.support.impl.WarehouseServiceImpl.checkStockAvailability]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,timeout_0; ''
20:16:57,339 DEBUG k.jdbc.datasource.SimpleDriverDataSource: 138 - Creating new JDBC Driver Connection to [jdbc:hsqldb:mem:testdb]
20:16:57,339 DEBUG .datasource.DataSourceTransactionManager: 206 - Acquired Connection [org.hsqldb.jdbc.JDBCConnection@34bde49d] for JDBC transaction
20:16:57,339 DEBUG .datasource.DataSourceTransactionManager: 223 - Switching JDBC Connection [org.hsqldb.jdbc.JDBCConnection@34bde49d] to manual commit
20:16:57,339 DEBUG .datasource.DataSourceTransactionManager: 755 - Initiating transaction commit
20:16:57,339 DEBUG .datasource.DataSourceTransactionManager: 266 - Committing JDBC transaction on Connection [org.hsqldb.jdbc.JDBCConnection@34bde49d]
20:16:57,339 DEBUG .datasource.DataSourceTransactionManager: 324 - Releasing JDBC Connection [org.hsqldb.jdbc.JDBCConnection@34bde49d] after transaction
20:16:57,339 DEBUG ramework.jdbc.datasource.DataSourceUtils: 327 - Returning JDBC Connection to DataSource
20:16:57,339  INFO          com.manuel.jordan.main.MainTest: 104 - result: true
20:16:57,339  INFO          com.manuel.jordan.main.MainTest: 105 - Post

Ошибка не была брошена, как это ожидалось..

Омикрон

Новый обновленный код:

@Service
@Transactional
@Scope("prototype")
public class WarehouseServiceImpl implements WarehouseService {

    private static final Logger logger = LoggerFactory.getLogger(WarehouseServiceImpl.class);

    private ProductService productService;

    @Autowired
    public WarehouseServiceImpl(ProductService productService){
        this.productService = productService;
    }

    @Override
    @Transactional(propagation = Propagation.REQUIRES_NEW, timeout=0)
    public boolean checkStockAvailability(Product product, BigDecimal quantity) {

        logger.info("Amount: {}", this.productService.getAmountProducts());
        ...     
        return true;

    }

}

Приведенный выше код одинаков для двух проектов: для одного, работающего с JdbcTemplate, все в порядке, ожидаемая ошибка выдается, но другой проект, работающий с Hibernate, не выдает ожидаемую ошибку. Ниже выводится результат.

08:27:06,782  INFO          com.manuel.jordan.main.MainTest: 102 - Pre
08:27:06,782 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
08:27:06,782 DEBUG m.hibernate4.HibernateTransactionManager: 367 - Creating new transaction with name [com.manuel.jordan.model.service.support.impl.WarehouseServiceImpl.checkStockAvailability]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,timeout_0; ''
08:27:06,783 DEBUG m.hibernate4.HibernateTransactionManager: 417 - Opened new Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@57ce634f updates=org.hibernate.engine.spi.ExecutableList@b8a7e43 deletions=org.hibernate.engine.spi.ExecutableList@35835fa orphanRemovals=org.hibernate.engine.spi.ExecutableList@56f71edb collectionCreations=org.hibernate.engine.spi.ExecutableList@7207cb51 collectionRemovals=org.hibernate.engine.spi.ExecutableList@2a27cb34 collectionUpdates=org.hibernate.engine.spi.ExecutableList@6892cc6f collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@6fd1660 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])] for Hibernate transaction
08:27:06,783 DEBUG m.hibernate4.HibernateTransactionManager: 427 - Preparing JDBC Connection of Hibernate Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@57ce634f updates=org.hibernate.engine.spi.ExecutableList@b8a7e43 deletions=org.hibernate.engine.spi.ExecutableList@35835fa orphanRemovals=org.hibernate.engine.spi.ExecutableList@56f71edb collectionCreations=org.hibernate.engine.spi.ExecutableList@7207cb51 collectionRemovals=org.hibernate.engine.spi.ExecutableList@2a27cb34 collectionUpdates=org.hibernate.engine.spi.ExecutableList@6892cc6f collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@6fd1660 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])]
08:27:06,783 DEBUG gine.jdbc.internal.LogicalConnectionImpl: 226 - Obtaining JDBC connection
08:27:06,783 DEBUG k.jdbc.datasource.SimpleDriverDataSource: 138 - Creating new JDBC Driver Connection to [jdbc:hsqldb:mem:testdb]
08:27:06,783 DEBUG gine.jdbc.internal.LogicalConnectionImpl: 232 - Obtained JDBC connection
08:27:06,783 DEBUG .transaction.spi.AbstractTransactionImpl: 160 - begin
08:27:06,783 DEBUG ransaction.internal.jdbc.JdbcTransaction:  69 - initial autocommit status: true
08:27:06,783 DEBUG ransaction.internal.jdbc.JdbcTransaction:  71 - disabling autocommit
08:27:06,784 DEBUG m.hibernate4.HibernateTransactionManager: 488 - Exposing Hibernate transaction as JDBC transaction [org.hsqldb.jdbc.JDBCConnection@4a6c18ad]
08:27:06,784 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
08:27:06,784 DEBUG m.hibernate4.HibernateTransactionManager: 362 - Found thread-bound Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@57ce634f updates=org.hibernate.engine.spi.ExecutableList@b8a7e43 deletions=org.hibernate.engine.spi.ExecutableList@35835fa orphanRemovals=org.hibernate.engine.spi.ExecutableList@56f71edb collectionCreations=org.hibernate.engine.spi.ExecutableList@7207cb51 collectionRemovals=org.hibernate.engine.spi.ExecutableList@2a27cb34 collectionUpdates=org.hibernate.engine.spi.ExecutableList@6892cc6f collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@6fd1660 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])] for Hibernate transaction
08:27:06,784 DEBUG m.hibernate4.HibernateTransactionManager: 472 - Participating in existing transaction
08:27:06,784 DEBUG ctory.support.DefaultListableBeanFactory: 249 - Returning cached instance of singleton bean 'transactionManager'
08:27:06,784 DEBUG m.hibernate4.HibernateTransactionManager: 362 - Found thread-bound Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@57ce634f updates=org.hibernate.engine.spi.ExecutableList@b8a7e43 deletions=org.hibernate.engine.spi.ExecutableList@35835fa orphanRemovals=org.hibernate.engine.spi.ExecutableList@56f71edb collectionCreations=org.hibernate.engine.spi.ExecutableList@7207cb51 collectionRemovals=org.hibernate.engine.spi.ExecutableList@2a27cb34 collectionUpdates=org.hibernate.engine.spi.ExecutableList@6892cc6f collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@6fd1660 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])] for Hibernate transaction
08:27:06,784 DEBUG m.hibernate4.HibernateTransactionManager: 472 - Participating in existing transaction
08:27:06,785 DEBUG                        org.hibernate.SQL: 109 - select count(*) as col_0_0_ from product product0_
08:27:06,785 DEBUG              org.hibernate.loader.Loader: 951 - Result set row: 0
08:27:06,786 DEBUG              org.hibernate.loader.Loader:1485 - Result row: 
08:27:06,786  INFO ervice.support.impl.WarehouseServiceImpl:  45 - Amount: 6
08:27:06,786 DEBUG m.hibernate4.HibernateTransactionManager: 755 - Initiating transaction commit
08:27:06,786 DEBUG m.hibernate4.HibernateTransactionManager: 551 - Committing Hibernate transaction on Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@57ce634f updates=org.hibernate.engine.spi.ExecutableList@b8a7e43 deletions=org.hibernate.engine.spi.ExecutableList@35835fa orphanRemovals=org.hibernate.engine.spi.ExecutableList@56f71edb collectionCreations=org.hibernate.engine.spi.ExecutableList@7207cb51 collectionRemovals=org.hibernate.engine.spi.ExecutableList@2a27cb34 collectionUpdates=org.hibernate.engine.spi.ExecutableList@6892cc6f collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@6fd1660 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])]
08:27:06,786 DEBUG .transaction.spi.AbstractTransactionImpl: 175 - committing
08:27:06,786 DEBUG ransaction.internal.jdbc.JdbcTransaction: 113 - committed JDBC Connection
08:27:06,786 DEBUG ransaction.internal.jdbc.JdbcTransaction: 126 - re-enabling autocommit
08:27:06,787 DEBUG m.hibernate4.HibernateTransactionManager: 633 - Closing Hibernate Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@57ce634f updates=org.hibernate.engine.spi.ExecutableList@b8a7e43 deletions=org.hibernate.engine.spi.ExecutableList@35835fa orphanRemovals=org.hibernate.engine.spi.ExecutableList@56f71edb collectionCreations=org.hibernate.engine.spi.ExecutableList@7207cb51 collectionRemovals=org.hibernate.engine.spi.ExecutableList@2a27cb34 collectionUpdates=org.hibernate.engine.spi.ExecutableList@6892cc6f collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@6fd1660 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])] after transaction
08:27:06,787 DEBUG gine.jdbc.internal.LogicalConnectionImpl: 246 - Releasing JDBC connection
08:27:06,787 DEBUG gine.jdbc.internal.LogicalConnectionImpl: 264 - Released JDBC connection
08:27:06,787  INFO          com.manuel.jordan.main.MainTest: 104 - result: true
08:27:06,787  INFO          com.manuel.jordan.main.MainTest: 105 - Post

Какая-то подсказка? DataAccess существует, конечно...

Answer 1

Просмотр ваших первых журналов (связанных с проблемой тайм-аута с recordInvoice против checkStockAvailability), они указывают на то, что поведение транзакций применяется правильно: на уровне кода Java транзакции запускаются и фиксируются. Единственная разница в журналах заключается в том, что с recordInvoice к базе данных выполняется фактический запрос checkStockAvailability нет такой вещи

Возможным ответом на это будет то, что если нет активности с базой данных, то нет транзакции на уровне базы данных. То, что вы имеете в Java-коде, отражается на уровне БД. Если, например, вы открываете консоль MySQL и вставляете что-то в таблицу, в конце вам нужно зафиксировать, чтобы увидеть результаты в БД.

В связи с вашей второй проблемой, где вы используете JdbcTemplate для одного теста и Hibernate (с HibernateTransactionManager) с другой стороны, глядя на исходный код транзакции Hibernate, кажется, что рассматриваются только значения, строго превышающие 0. Итак, простой тест, который включает установку времени ожидания в одну секунду в транзакционном методе checkStockAvailability можно добавить Thread.sleep(1500) может показывать, что значения 0 секунд для тайм-аута просто игнорируются, объясняя результаты ваших тестов.