[transaction] propagation and row lock 실전편

개발/spring

[transaction] propagation and row lock 실전편

방푸린 2023. 1. 5. 13:57

환경: springboot 2.6.2, java11 기반의 spring-jpa project

1. chained transaction

@Transactional(transactionManager = Constants.CHAINED_TRANSACTION_MANAGER)
public void depositWithCredential(MoneyExchangeCredentialRequest credentialRequest) {
    log.warn("> outside tx name: {}", TransactionSynchronizationManager.getCurrentTransactionName());
    ...

2023-01-05 09:39:09 DEBUG [s.t.s.AbstractPlatformTransactionManager.getTransaction      : 370][http-nio-8600-exec-8] Creating new transaction with name [com.MoneyExchangeService.depositWithCredential]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; 'chainedTransactionManager'
2023-01-05 09:39:09 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-8] Opened new EntityManager [SessionImpl(1728738865<open>)] for JPA transaction
2023-01-05 09:39:09 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-8] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@6335fe08]
2023-01-05 09:39:09 DEBUG [s.t.s.AbstractPlatformTransactionManager.getTransaction      : 370][http-nio-8600-exec-8] Creating new transaction with name [com.MoneyExchangeService.depositWithCredential]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; 'chainedTransactionManager'
2023-01-05 09:39:09 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-8] Opened new EntityManager [SessionImpl(641170442<open>)] for JPA transaction
2023-01-05 09:39:09 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-8] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@23d44be1]
2023-01-05 09:39:09 DEBUG [s.t.s.AbstractPlatformTransactionManager.getTransaction      : 370][http-nio-8600-exec-8] Creating new transaction with name [com.MoneyExchangeService.depositWithCredential]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; 'chainedTransactionManager'
2023-01-05 09:39:09 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-8] Opened new EntityManager [SessionImpl(391846484<open>)] for JPA transaction
2023-01-05 09:39:09 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-8] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@5b527309]

3개의 DB가 물려있기 때문에 총 3번의 transaction이 열림

2. 엄마 transaction 확인, 편의상 앞으로 dWC라고 부를 예정

2023-01-05 09:39:09 WARN > outside tx name: com.MoneyExchangeService.depositWithCredential

3. propagation = REQUIRES_NEW

createDailyMoneyExchangeIfAbsentAndGetWithLock 함수 안을 살펴본다.

@Transactional(transactionManager = Constants.CHAINED_TRANSACTION_MANAGER)
public void depositWithCredential(MoneyExchangeCredentialRequest credentialRequest) {
    log.warn("> outside tx name: {}", TransactionSynchronizationManager.getCurrentTransactionName());
    ...
    MoneyExchange dailyExchange = createDailyMoneyExchangeIfAbsentAndGetWithLock(request);
    ...
    
}

private MoneyExchange createDailyMoneyExchangeIfAbsentAndGetWithLock(MoneyExchangeRequest request) {
    MoneyExchange.PK pk = createDailyMoneyExchangePK(request);
    if(moneyExchangeRepository.findById(pk).isEmpty()) { //조회 1
        moneyExchangeEntityService.createMoneyExchangeFromNewTransaction(new MoneyExchange(pk)); //새로운 트랜, 조회 2 + save
    }
    return moneyExchangeRepository.findOneWithLock(pk); //select for update; start lock
}

//다른 서비스

@Transactional(transactionManager = Constants.USER_TRANSACTION_MANAGER, propagation = Propagation.REQUIRES_NEW)
public void createMoneyExchangeFromNewTransaction(MoneyExchange moneyExchange) {
    log.warn("> createMoneyExchangeFromNewTransaction requires new tx name: {}", TransactionSynchronizationManager.getCurrentTransactionName());
    moneyExchangeRepository.save(moneyExchange);
}

//레파지토리

@Lock(LockModeType.PESSIMISTIC_WRITE)
@Query("SELECT c FROM MoneyExchange c WHERE c.pk = :pk")
MoneyExchange findOneWithLock(@Param("pk") MoneyExchange.PK pk);

2023-01-05 09:45:58 WARN  [c.n.g.s.m.MoneyExchangeService          .depositWithCredentia: 242][http-nio-8600-exec-1] > outside tx name: com.MoneyExchangeService.depositWithCredential

...

2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-1] Found thread-bound EntityManager [SessionImpl(1294697638<open>)] for JPA transaction
2023-01-05 09:45:58 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 470][http-nio-8600-exec-1] Participating in existing transaction
Hibernate: 
    select

    from
        hd_moneyexchange moneyexcha0_ 
    where

2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-1] Found thread-bound EntityManager [SessionImpl(1294697638<open>)] for JPA transaction
2023-01-05 09:45:58 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 429][http-nio-8600-exec-1] Suspending current transaction, creating new transaction with name [com.MoneyExchangeEntityService.createMoneyExchangeFromNewTransaction]

2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-1] Opened new EntityManager [SessionImpl(866488609<open>)] for JPA transaction
2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-1] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@57ad1a62]
2023-01-05 09:45:58 WARN  [c.n.g.s.MoneyExchangeEntityService      .createMoneyExchangeF:  28][http-nio-8600-exec-1] > createMoneyExchangeFromNewTransaction requires new tx name: com.MoneyExchangeEntityService.createMoneyExchangeFromNewTransaction
2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-1] Found thread-bound EntityManager [SessionImpl(866488609<open>)] for JPA transaction
2023-01-05 09:45:58 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 470][http-nio-8600-exec-1] Participating in existing transaction
Hibernate: 
    select
       
    from
        hd_moneyexchange moneyexcha0_ 
    where
       
2023-01-05 09:45:58 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-1] Initiating transaction commit
2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-1] Committing JPA transaction on EntityManager [SessionImpl(866488609<open>)]
Hibernate: 
    insert 
    into
        hd_moneyexchange
       
    values

2023-01-05 09:45:58 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-1] Closing JPA EntityManager [SessionImpl(866488609<open>)] after transaction
2023-01-05 09:45:58 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-1] Resuming suspended transaction after completion of inner transaction
Hibernate: 
    select
       
    from
        hd_moneyexchange moneyexcha0_ 
    where
    
    for update

로그를 보면 같은 select가 총 3번 실행하는 것을 알 수 있는데,

하나는 if절 안 isEmpty를 위해
두 번째는 새로운 서비스 안에서 새로운 transaction(자식 transaction, cMEFNT)을 시작하고 save 전에 select
- 로그를 보면 알겠지만 dWC를 중지하고 새로운 transaction을 여는 것을 볼 수 있다.
- 여기서는 transaction manager가 chained가 아니라서 한 번의 transaction만 열고 있다.
- 이는 save 시 영속성 있는 entity가 없어서 select가 한번 더 호출되는 것으로 보인다.
- https://stackoverflow.com/questions/45635827/how-do-i-stop-spring-data-jpa-from-doing-a-select-before-a-save
- 그리고 자식 transaction이 종료됨에 따라 insert
그리고 다시 부모 transaction으로 돌아가 row lock을 위해 조회

~~사실 이 부분에는 불필요한 로직이 있어서 수정할 예정이다.~~

다만 자식 transaction과 propagation_new의 관계를 보기 좋은 예시라 들고 왔는데, 로그를 보면 자식 transaction가 끝나고 insert commit 후 다시 엄마 transaction으로 돌아가는 것을 볼 수 있다.

4. 마지막의 row lock을 위한 테스트

@Lock(LockModeType.PESSIMISTIC_WRITE)

수동 db조작으로 테스트

select for update가 실행되고 다음 부분에 디버그를 걸어 임시 정지, db를 조작하며 테스트

해당 row select 가능(readable)
해당 row update 불가능(pending)
다른 row update 가능
select for update가 끝나고(transaction 종료) 해당 row update 가능

program으로 테스트

유저 a에 대한 row 삽입
유저 b에 대한 row 삽입
유저 a에 대한 api 호출 -> 해당 row lock -> sleep
유저 b에 대한 api호출 -> 역시 해당 row lock (조회됨) -> sleep

-> row 단위 lock 확인

유저 a에 대한 row 삽입
유저 a에 대한 api 호출 -> 해당 row lock -> sleep
유저 a에 대한 api 호출 -> sleep도 못가고 select for update에서 pending -> timeout으로 에러처리

-> 같은 row 일 때 lock 되는 것 확인

default timeout 1분(1분 뒤 에러처리)

기본 값은 DB 설정 값을 따른다.

mysql 기준

확인 쿼리는 아래..

select @@innodb_lock_wait_timeout

//lock 이후에 sleep
>>>>>>>>sleeping

//신규 요청
2023-01-05 11:36:10 INFO  [c.n.g.common.filter.RequestLogFilter    .doFilter            :  34][http-nio-8600-exec-2] [REQUEST] [POST] /api/external/money
...
Hibernate: 
    select
      
    from
        hd_moneyexchange moneyexcha0_ 
    where
     
    for update
            
2023-01-05 11:37:10 WARN  [o.h.engine.jdbc.spi.SqlExceptionHelper  .logExceptions       : 137][http-nio-8600-exec-2] SQL Error: 1205, SQLState: 40001
2023-01-05 11:37:10 ERROR [o.h.engine.jdbc.spi.SqlExceptionHelper  .logExceptions       : 142][http-nio-8600-exec-2] Lock wait timeout exceeded; try restarting transaction
2023-01-05 11:37:10 DEBUG [s.t.s.AbstractPlatformTransactionManager.processRollback     : 833][http-nio-8600-exec-2] Initiating transaction rollback
..
Response body: {"header":{"status":500,"message":"could not extract ResultSet; SQL [n/a]; nested exception is org.hibernate.PessimisticLockException: could not extract ResultSet","isSuccessful":false}}

timeout 설정 방법

## 전역 설정
spring.jpa.properties.javax.persistence.query.timeout=5000

//

## DB config 별 설정이 나눠져 있다면
a.jpa.properties.javax.persistence.query.timeout=4000

@ConfigurationProperties(prefix = "a.jpa")
public static class AJpaProperties {
    private Map<String, String> properties = new HashMap<>();

    public Map<String, String> getProperties() {
        return properties;
    }

    public void setProperties(Map<String, String> properties) {
        this.properties = properties;
    }
}

// or //

Map<String,Object> properties = new HashMap();
properties.put("javax.persistence.query.timeout", 5000);
EntityManager entityManager = entityManagerFactory.createEntityManager(properties);

//쿼리 별 설정
//전역 설정이 있어도 override됨
@Lock(LockModeType.PESSIMISTIC_WRITE)
@Query("SELECT c FROM MoneyExchange c WHERE c.pk = :pk")
@QueryHints({@QueryHint(name = "javax.persistence.lock.timeout", value = "6000")})
   MoneyExchange findOneWithLock(@Param("pk") MoneyExchange.PK pk);

설정 후 로그, local timeout(6초)를 따른다.

2023-01-05 13:22:07 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 470][http-nio-8600-exec-2] Participating in existing transaction
    select
       
    from
        hd_moneyexchange moneyexcha0_ 
    where
       for update
            
2023-01-05 13:22:12 WARN  [com.zaxxer.hikari.pool.ProxyConnection  .checkException      : 182][http-nio-8600-exec-2] HikariPool-1 - Connection com.mysql.cj.jdbc.ConnectionImpl@23ae77d9 marked as broken because of SQLSTATE(null), ErrorCode(0)
com.mysql.cj.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request

참고) queryHint에 다른 옵션들도 있을까 싶어서 아래 옵션을 주었으나 무시되었다. 아직까지도 지원을 하지 않는 모양

@QueryHints({@QueryHint(name = "javax.persistence.lock.scope", value = "EXTENDED")})

..
[http-nio-8600-exec-1] HHH000121: Ignoring unrecognized query hint [javax.persistence.lock.scope]

참고) spring-jpa lock option종류

LockModeType.PESSIMISTIC_WRITE
일반적인 옵션. 데이터베이스에 쓰기 락
다른 트랜잭션에서 읽기도 쓰기도 못함. (배타적 잠금)
LockModeType.PESSIMISTIC_READ
반복 읽기만 하고 수정하지 않는 용도로 락을 걸 때 사용
다른 트랜잭션에서 읽기는 가능함. (공유 잠금)
LockModeType.PESSINISTIC_FORCE_INCREMENT
Version 정보를 사용하는 비관적 락

참고) mysql read-lock

https://dev.mysql.com/doc/refman/5.7/en/innodb-locking-reads.html

참고) 테이블이 lock 걸린 경우 확인 쿼리; row lock은 안 잡힘

SHOW OPEN TABLES 
where `database` = ''
and `table` = ''
;

row lock은 아래 쿼리로 조회 시 row lock이 있다고는 알 수 있는데, 정작 누가 걸린 건지는 안 알려줌..

SHOW ENGINE INNODB STATUS;

5. 나머지 엄마 transaction 로직 확인

@Transactional(transactionManager = Constants.CHAINED_TRANSACTION_MANAGER)
public void depositWithCredential(MoneyExchangeCredentialRequest credentialRequest) {
    log.warn("> outside tx name: {}", TransactionSynchronizationManager.getCurrentTransactionName());
    ...
    MoneyExchange dailyExchange = createDailyMoneyExchangeIfAbsentAndGetWithLock(request);
    ...
    
    runAndSaveErrorLogIfFail(request, money, () -> {
        saves(...); //엄마 트랜; 바로 커밋 안함
        System.out.println(">> before withdraw");
        log.warn("> before throw tx name: {}", TransactionSynchronizationManager.getCurrentTransactionName());
        throw new Exception();
    });
}

private void runAndSaveErrorLogIfFail(MoneyExchangeRequest request, long availableMoney, Runnable runnable) {
    try {
        log.warn("> runAndSaveErrorLogIfFail Thread Name before: " + Thread.currentThread().getName());
        runnable.run();
    } catch (AException e) {
        log.error("MoneyExchangeService.runAndSaveErrorLogIfFail() AException, message: {}, request: {}", e.getExceptionMessage(), request);
        saveErrorLog(request, e.getExceptionMessage(), availableMoney);
        throw e;
    } catch (Exception e) {
        log.error("MoneyExchangeService.runAndSaveErrorLogIfFail() Exception, message: {}, request: {}", e.getMessage(), request);
        saveErrorLog(request, e.getMessage(), availableMoney);
        throw e;
    }
}

private void saves(...) {
    // 저장1
    long realDepositMoney = sendGameMail(request, user, configurations.getExchangeGameConfiguration());
    // 저장2
    saveDailyMoneyExchange(dailyExchange, changedMoney); //엄마 트랜
    // 저장3
    saveDailyMoneyExchangeLog(request, user, changedMoney, originAvailableMoney); //엄마 트랜
}

Hibernate: //저장1; 
    select

    from
        hd_user_notice usernotice0_ 
    where
  
...
2023-01-05 10:15:04 WARN  [c.n.g.s.m.MoneyExchangeService          .saveDailyMoneyExchan: 394][http-nio-8600-exec-2] > saveDailyMoneyExchangeLog tx name: com.MoneyExchangeService.depositWithCredential
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-2] Found thread-bound EntityManager [SessionImpl(1213852261<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 470][http-nio-8600-exec-2] Participating in existing transaction
Hibernate:  //저장3; 부모 transaction
    insert 
    into
        hd_moneyexchange_log
        
    values
        
2023-01-05 10:15:04 WARN  [c.n.g.s.m.MoneyExchangeService          .saveDailyMoneyExchan: 397][http-nio-8600-exec-2] > saveDailyMoneyExchangeLog tx name: com.MoneyExchangeService.depositWithCredential
>> before withdraw
2023-01-05 10:15:04 WARN  [c.n.g.s.m.MoneyExchangeService          .lambda$depositWithCr: 253][http-nio-8600-exec-2] > before throw tx name: com.MoneyExchangeService.depositWithCredential
...
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-2] Found thread-bound EntityManager [SessionImpl(157605982<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 429][http-nio-8600-exec-2] Suspending current transaction, creating new transaction with name [com.MoneyExchangeLogEntityService.logFromNewTransaction]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-2] Opened new EntityManager [SessionImpl(251535742<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-2] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@1bd03ae5]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-2] Found thread-bound EntityManager [SessionImpl(1213852261<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 429][http-nio-8600-exec-2] Suspending current transaction, creating new transaction with name [com.MoneyExchangeLogEntityService.logFromNewTransaction]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-2] Opened new EntityManager [SessionImpl(830560897<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-2] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@1afe4eee]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-2] Found thread-bound EntityManager [SessionImpl(2044396758<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 429][http-nio-8600-exec-2] Suspending current transaction, creating new transaction with name [com.MoneyExchangeLogEntityService.logFromNewTransaction]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 412][http-nio-8600-exec-2] Opened new EntityManager [SessionImpl(1710520606<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doBegin             : 440][http-nio-8600-exec-2] Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7f696057]
2023-01-05 10:15:04 WARN  [c.n.g.s.MoneyExchangeLogEntityService   .logFromNewTransactio:  22][http-nio-8600-exec-2] > error logFromNewTransaction tx name: com.MoneyExchangeLogEntityService.logFromNewTransaction
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-2] Found thread-bound EntityManager [SessionImpl(830560897<open>)] for JPA transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 470][http-nio-8600-exec-2] Participating in existing transaction
Hibernate: //에러 로그 삽입
    insert 
    into
        hd_moneyexchange_log
      
    values
      
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-2] Initiating transaction commit
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-2] Committing JPA transaction on EntityManager [SessionImpl(1710520606<open>)]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-2] Closing JPA EntityManager [SessionImpl(1710520606<open>)] after transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-2] Resuming suspended transaction after completion of inner transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-2] Initiating transaction commit
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-2] Committing JPA transaction on EntityManager [SessionImpl(830560897<open>)]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-2] Closing JPA EntityManager [SessionImpl(830560897<open>)] after transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-2] Resuming suspended transaction after completion of inner transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-2] Initiating transaction commit
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-2] Committing JPA transaction on EntityManager [SessionImpl(251535742<open>)]
2023-01-05 10:15:04 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-2] Closing JPA EntityManager [SessionImpl(251535742<open>)] after transaction
2023-01-05 10:15:04 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-2] Resuming suspended transaction after completion of inner transaction
2023-01-05 10:15:06 DEBUG [s.t.s.AbstractPlatformTransactionManager.processRollback     : 833][http-nio-8600-exec-2] Initiating transaction rollback
2023-01-05 10:15:06 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doRollback          : 583][http-nio-8600-exec-2] Rolling back JPA transaction on EntityManager [SessionImpl(2044396758<open>)]
2023-01-05 10:15:06 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-2] Closing JPA EntityManager [SessionImpl(2044396758<open>)] after transaction
2023-01-05 10:15:06 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-2] Resuming suspended transaction after completion of inner transaction
2023-01-05 10:15:06 DEBUG [s.t.s.AbstractPlatformTransactionManager.processRollback     : 833][http-nio-8600-exec-2] Initiating transaction rollback
2023-01-05 10:15:06 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doRollback          : 583][http-nio-8600-exec-2] Rolling back JPA transaction on EntityManager [SessionImpl(1213852261<open>)]
2023-01-05 10:15:06 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-2] Closing JPA EntityManager [SessionImpl(1213852261<open>)] after transaction
2023-01-05 10:15:06 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-2] Resuming suspended transaction after completion of inner transaction
2023-01-05 10:15:06 DEBUG [s.t.s.AbstractPlatformTransactionManager.processRollback     : 833][http-nio-8600-exec-2] Initiating transaction rollback
2023-01-05 10:15:06 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doRollback          : 583][http-nio-8600-exec-2] Rolling back JPA transaction on EntityManager [SessionImpl(157605982<open>)]
2023-01-05 10:15:06 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-2] Closing JPA EntityManager [SessionImpl(157605982<open>)] after transaction
2023-01-05 10:15:06 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-2] Resuming suspended transaction after completion of inner transaction
2023-01-05 10:15:06 DEBUG [.m.m.a.ExceptionHandlerExceptionResolver.doResolveHandlerMeth: 416][http-nio-8600-exec-2] Using @ExceptionHandler

private void runAndSaveErrorLogIfFail(MoneyExchangeRequest request, long availableMoney, Runnable runnable) {

runnable을 받는 함수는 처음 봐서 특이점이 있나 싶었는데, 원작자에게 물어보니 try-catch 에러로그 부분을 다양한 곳에서 공통으로 쓰려고 하셨다고 한다. 즉, logic 함수만 갈아 끼고 error발생 시 처리하는 부분을 공통화하기 위한 로직이었다. 예전 pr때 catch부분이 너무 똑같고 많이 반복된다는 지적이 있었는데 그걸 보완하기 위한 코드인 듯. 멀티스레드나 그런 걸 위한 건 아니다.

로그를 보면서 코드를 분석해 본다.

저장 1에 대한 select 실행
저장 2에 hibernate로그는 없음
saves 함수의 저장 3번(saveDailyMoneyExchangeLog) 로직이 실행되고(엄마 transaction)
- 이 부분이 왜 실행되는지 모르겠다. saves 함수를 나온 것도 아니고, throw 전의 로그를 찍기도 전에 insert 로그가 찍힌다. 물론 나중에 롤백되긴 하는데.. 다른 insert문은 하나도 안 찍히고 마지막 거만 찍히는 게 이해가 잘 안 가는 부분.
saves를 나오고 throw를 만나서 새로운 transaction이 열림(자식 transaction시작; creating new transaction with name logFromNewTransaction)
transatcion manager가 chained 여서 transaction이 세 번 열림..
에러 로그를 insert 하고 commit 하고 엄마 transaction에게 돌아가고
엄마 transaction은 exception을 전파받아 doRollback을 세 번(엄마 transaction자체가 chained transaction) 실행
그리고 마지막으로 exception은 @ExceptionHandler를 타고 최종 전파된다.

throw를 지우고 성공 시 로그

Hibernate: //저장1; 
    select

    from
        hd_user_notice usernotice0_ 
    where
  
...
2023-01-05 14:07:36 WARN  [c.n.g.s.m.MoneyExchangeService          .saveDailyMoneyExchan: 396][http-nio-8600-exec-1] > saveDailyMoneyExchangeLog tx name: com.MoneyExchangeService.depositWithCredential
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doGetTransaction    : 375][http-nio-8600-exec-1] Found thread-bound EntityManager [SessionImpl(425779152<open>)] for JPA transaction
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.handleExistingTransa: 470][http-nio-8600-exec-1] Participating in existing transaction
Hibernate: //저장3 쿼리 실행
    insert 
    into
        hd_moneyexchange_log
      
    values
#### saves 함수 밖...      
2023-01-05 14:07:36 WARN  [c.n.g.s.m.MoneyExchangeService          .lambda$depositWithCr: 256][http-nio-8600-exec-1] > before throw tx name: com.MoneyExchangeService.depositWithCredential
##static close
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-1] Initiating transaction commit
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-1] Committing JPA transaction on EntityManager [SessionImpl(1732642577<open>)]
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-1] Closing JPA EntityManager [SessionImpl(1732642577<open>)] after transaction
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-1] Resuming suspended transaction after completion of inner transaction
##log close
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-1] Initiating transaction commit
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-1] Committing JPA transaction on EntityManager [SessionImpl(425779152<open>)]
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-1] Closing JPA EntityManager [SessionImpl(425779152<open>)] after transaction
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-1] Resuming suspended transaction after completion of inner transaction
## user close
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.processCommit       : 740][http-nio-8600-exec-1] Initiating transaction commit
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCommit            : 557][http-nio-8600-exec-1] Committing JPA transaction on EntityManager [SessionImpl(1465294398<open>)]
Hibernate: //저장1 쿼리 실행
    insert 
    into
        hd_user_notice
     
    values
     
Hibernate: 
    update //저장2 쿼리 실행
        hd_moneyexchange 
    set
       
    where
       
2023-01-05 14:07:36 DEBUG [o.s.orm.jpa.JpaTransactionManager       .doCleanupAfterComple: 648][http-nio-8600-exec-1] Closing JPA EntityManager [SessionImpl(1465294398<open>)] after transaction
2023-01-05 14:07:36 DEBUG [s.t.s.AbstractPlatformTransactionManager.cleanupAfterCompleti: 996][http-nio-8600-exec-1] Resuming suspended transaction after completion of inner transaction

디버그를 걸고 보니 위 원인을 알 수 있었다.

save 함수 구현체에 있는 isNew부분이 포인트다.

isNew() 메서드는 새로운 Entity를 판단하기 위해 ID값을 확인하는데 기본 전략은 아래와 같다.

ID의 타입이 객체 타입(reference; string) 일 때: null
ID의 타입이 기본 타입(primitive) 일 때: 0

merge vs persist?

merge는 Detached 상태의 Entity를 다시 영속화 하는데 사용되고 persist는 최초 생성된 Entity를 영속화 하는데 사용된다.

Merge : Detached Entity ⇒ Managed Entity
Persist : New Entity ⇒ Managed Entity

em.merge() is trying to retrieve an existing entity from DB with a SELECT query and update it. So if the entity was never persisted, this will waste some CPU cycles. On the other side em.persist() will only produce one INSERT query.

참고로 entity가 persisted, 즉 영속된 entity인지는 EntityManager안의 contains함수를 통해 알 수 있다.

em.contains(entity)

저장 1

pk(객체 타입) is not null -> merge -> 영속성 없음, select 조회, 영속성 부여 -> 조회 결과가 없으니 후에 insert 예약 -> seq가 null로 인서트 예정이었으나 DB에서 넣어줌 -> 트랜젝션 종료쯤 commit시 날아감

저장 2

자식 transaction으로 save한 결과의 entity를 넘겨 받음 -> pk(객체 타입) is not null -> merge -> em.contains(entity) == true -> 영속성 있음, 추가 select 없음 -> dirty checking, 수정된거 확인 후에 update 예약 -> 트랜젝션 종료쯤 commit시 날아감

저장 3

key가 auto increment로 생성되는 seq(Long) 값이고 최초에는 null. -> persist -> id(seq)값을 가져오기 위해 insert를 쏴서 얻음

>> 그래서 중간에 insert 쿼리가 뜬금없이 날아감

그리고 저장 3의 persist 된 엔티티는 후에 수정된 사항이 없어서 추가 insert문이 안 날아간다.

save 호출 후 엔티티를 사용할 일이 있다면(추가 수정건 등) 영속상태의 엔티티를 반환받아서 사용하는 게 성능에 좋다(추가 select문이 안 날아간다).

참고) chained transaction manager

현재 chained transaction manager 설정이 아래와 같고 저장 1은 USER, 저장 2도 USER, 저장 3은 LOG transaction manager에 속한다.

@Primary
@Bean(Constants.CHAINED_TRANSACTION_MANAGER)
public PlatformTransactionManager transactionManager(
        @Qualifier(Constants.USER_TRANSACTION_MANAGER)
                PlatformTransactionManager userPlatformTransactionManager,
        @Qualifier(Constants.LOG_TRANSACTION_MANAGER)
                PlatformTransactionManager logPlatformTransactionManager,
        @Qualifier(Constants.STATIC_TRANSACTION_MANAGER)
                PlatformTransactionManager staticPlatformTransactionManager) {
    return new ChainedTransactionManager(userPlatformTransactionManager,
            logPlatformTransactionManager,
            staticPlatformTransactionManager);
}

transaction USER begin
  transaction LOG begin
    transaction STATIC begin
    transaction STATIC commit
  transaction LOG commit -> error rollbacks LOG, USER
transaction USER commit -> error, only rollbacks USER

지정된 순서대로 트랜잭션이 실행되고, 지정된 역순으로 트랜잭션이 종료된다.
다시 말해, 에러를 내기 쉬운 트랜잭션을 마지막에 지정해서 트랜잭션 종료 작업이 최초로 호출되도록 해야 한다
왜냐면 에러를 낼 가능성이 높은 트랜잭션이 최초로 롤백이 돼야 그 뒤의 다른 트랜잭션도 따라서 롤백되기 때문이다. ChainedTransactionManager는 단지 트랜잭션 시작과 종료를 동시에 해줄 뿐이지 Two Phase Commit을 지원하는 게 아니라서 이미 다른 트랜잭션이 커밋된 상황에서 하나의 트랜잭션이 롤백 됐다고 해서 이미 커밋된 것들이 다시 롤백되지는 않는다.
따라서 가장 위험한 요소를 최초로 커밋/롤백 시도 하도록 해야 한다.

참고 jpa save

https://leegicheol.github.io/jpa/jpa-is-new/

Spring Data JPA isNew 메서드

김영한 : 실전! 스프링 데이터 JPA 강의를 공부한 내용입니다.

leegicheol.github.io

https://taesan94.tistory.com/266

Spring Data Jpa Insert 할 때 Select가 나가네..

문제 상황 설계한 Entity의 id가 Auto Increament값이 아니다. 생성자가 호출되는 시점에 fk의 조합으로 생성된다. makeReservedSeatId 함수에서 만들어진다. @Entity @Table(name = "reserved_seat") public class ReservedSeat

taesan94.tistory.com

728x90