지난 시간에는 모니터링으로 성능을 측정하고 JPA의 N+1 문제를 해결하고 인덱스를 적용해서 성능을 개선하였습니다.
이번에는 트랜잭션을 최적화한 내용에 대해서 공유하려고 합니다.
성능 측정 및 성능 개선에 대한 내용은 다음의 링크를 참조해 주세요.
애플리케이션 성능 개선 Part 1 (feat. 병목 현상, N+1, 인덱스)
트랜잭션 최적화의 필요성
트랜잭션은 데이터의 일관성과 무결성을 보장하는 핵심 메커니즘입니다. 특히 여러 개의 쿼리를 조합해 처리하는 경우, 트랜잭션 경계를 어떻게 지정하느냐에 따라 의도한 대로 작동할 수도 있고, 전혀 다른 결과를 초래할 수도 있습니다. 또한 트랜잭션 구성에 따라 애플리케이션의 성능에도 큰 영향을 줄 수 있으므로, 이를 제대로 이해하고 최적화하는 것이 중요합니다.
예를 들어, 하나의 트랜잭션 안에 외부 API 호출이나 불필요하게 많은 쿼리가 포함되면, 트랜잭션 완료까지 시간이 오래 걸립니다. 이로 인해 다른 트랜잭션이 대기 상태에 놓이고, DB 커넥션(Connection) 점유 시간이 길어지면서 커넥션 부족으로 처리 속도가 저하되는 문제가 발생할 수 있습니다.
기존 코드에서의 문제점
@Transactional 선언 ❌
public StoreResponse createStore(StoreRequest request, List<MultipartFile> images) {
log.info("StoreService.createStore() start");
final StoreCategory category = categoryService.findCategoryById(request.categoryId());
final Location location = locationService.getLocation(request.locationId());
final LocalDate now = LocalDate.now();
final LocalDate startDate = request.startDate();
StoreStatus storeStatus;
if (request.startDate().isAfter(now)) {
storeStatus = StoreStatus.PENDING;
} else if (request.endDate().isBefore(now)) {
storeStatus = StoreStatus.DISMISSED;
} else {
storeStatus = StoreStatus.RESOLVED;
}
log.debug("createStore storeStatus={}", storeStatus);
Store store = Store.builder()
.name(request.name())
.description(request.description())
.storeStatus(storeStatus)
.startDate(request.startDate())
.endDate(request.endDate())
.websiteUrl(request.websiteUrl())
.snsUrl(request.snsUrl())
.category(category)
.location(location)
.build();
storeRepository.save(store);
final List<StoreOperatingHour> operatingHours =
operatingHourService.createOperatingHours(store, request.operatingHours());
log.debug("createStore operatingHours={}", operatingHours);
store.addOperatingHours(operatingHours);
final List<StoreImage> storeImages =
storeImageService.createUploadImages(store, images, request.thumbnailIndex());
log.debug("createStore storeImages={}", storeImages);
store.addImages(storeImages);
log.info("StoreService.createStore() end");
return StoreResponse.from(store);
}
코드의 동작 흐름은 다음과 같습니다.
- 팝업스토어 카테고리를 조회
- 위치 주소를 조회
- 날짜로 팝업스토어 상태를 결정하는 로직
- 팝업스토어 저장
- 팝업스토어 운영 시간 저장
- S3 이미지 업로드
- 팝업스토어 이미지 저장
2025-09-19T20:16:46.018+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-19T20:16:46.119+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] k.c.p.s.controller.StoreApiController : createStore StoreRequest=StoreRequest[name=팝업 테스트1, description=팝업 테스트1, startDate=2025-09-19, endDate=2025-10-03, websiteUrl=, snsUrl=, thumbnailIndex=0, categoryId=1, locationId=16, operatingHours=[StoreOperatingHourRequest[days=월, startTime=08:00, endTime=20:00]]], images size=1
2025-09-19T20:16:46.129+09:00 INFO 5812 --- [pinup] [nio-8080-exec-3] k.co.pinup.stores.service.StoreService : StoreService.createStore() start
2025-09-19T20:16:46.129+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(24846046<open>)] for JPA transaction
2025-09-19T20:16:46.129+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2025-09-19T20:16:46.129+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@34f26b7e]
2025-09-19T20:16:46.130+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:16:46.136+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.SQL : select sc1_0.id,sc1_0.created_at,sc1_0.name,sc1_0.updated_at from store_categories sc1_0 where sc1_0.id=?
2025-09-19T20:16:46.136+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
2025-09-19T20:16:46.139+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:16:46.139+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-19T20:16:46.139+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(24846046<open>)]
2025-09-19T20:16:46.141+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-19T20:16:46.144+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(24846046<open>)] for JPA transaction
2025-09-19T20:16:46.144+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2025-09-19T20:16:46.144+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@4882bf61]
2025-09-19T20:16:46.144+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:16:46.145+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.SQL : select l1_0.id,l1_0.address,l1_0.address_detail,l1_0.created_at,l1_0.latitude,l1_0.longitude,l1_0.name,l1_0.sido,l1_0.sigungu,l1_0.updated_at,l1_0.zonecode from locations l1_0 where l1_0.id=?
2025-09-19T20:16:46.145+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [16]
2025-09-19T20:16:46.147+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:16:46.147+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-19T20:16:46.147+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(24846046<open>)]
2025-09-19T20:16:46.148+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-19T20:16:46.149+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] k.co.pinup.stores.service.StoreService : createStore storeStatus=RESOLVED
2025-09-19T20:16:46.150+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(24846046<open>)] for JPA transaction
2025-09-19T20:16:46.150+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-09-19T20:16:46.152+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@61afdfbb]
2025-09-19T20:16:46.152+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-19T20:16:46.163+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.SQL : insert into stores (category_id,created_at,description,end_date,is_deleted,location_id,name,sns_url,start_date,store_status,view_count,website_url) values (?,?,?,?,?,?,?,?,?,?,?,?)
2025-09-19T20:16:46.163+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
2025-09-19T20:16:46.163+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (2:TIMESTAMP) <- [2025-09-19T20:16:46.156339900]
2025-09-19T20:16:46.163+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (3:VARCHAR) <- [팝업 테스트1]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (4:DATE) <- [2025-10-03]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (5:BOOLEAN) <- [false]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (6:BIGINT) <- [16]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (7:VARCHAR) <- [팝업 테스트1]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (8:VARCHAR) <- []
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (9:DATE) <- [2025-09-19]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (10:VARCHAR) <- [RESOLVED]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (11:BIGINT) <- [0]
2025-09-19T20:16:46.164+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (12:VARCHAR) <- []
2025-09-19T20:16:46.170+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-19T20:16:46.170+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-19T20:16:46.170+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(24846046<open>)]
2025-09-19T20:16:46.189+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-19T20:16:46.190+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] k.co.pinup.stores.service.StoreService : createStore operatingHours=[kr.co.pinup.storeoperatinghour.StoreOperatingHour@11e8cbb2]
2025-09-19T20:16:46.190+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(24846046<open>)] for JPA transaction
2025-09-19T20:16:46.190+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [kr.co.pinup.storeimages.service.StoreImageService.createUploadImages]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-09-19T20:16:46.190+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@11c13342]
2025-09-19T20:16:46.190+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [kr.co.pinup.storeimages.service.StoreImageService.createUploadImages]
2025-09-19T20:16:46.381+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(24846046<open>)] for JPA transaction
2025-09-19T20:16:46.381+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-19T20:16:46.381+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.saveAll]
2025-09-19T20:16:46.386+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.SQL : insert into store_images (created_at,image_url,is_deleted,is_thumbnail,store_id) values (?,?,?,?,?)
2025-09-19T20:16:46.387+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:TIMESTAMP) <- [2025-09-19T20:16:46.382263100]
2025-09-19T20:16:46.387+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [http://127.0.0.1:4566/pinup/store/dd4d6e4f-5371-44dd-96f9-0d5d337fa013_%EC%8A%A4%ED%81%AC%EB%A6%B0%EC%83%B7%202025-09-19%20165430.png]
2025-09-19T20:16:46.387+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (3:BOOLEAN) <- [false]
2025-09-19T20:16:46.387+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (4:BOOLEAN) <- [true]
2025-09-19T20:16:46.387+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (5:BIGINT) <- [15]
2025-09-19T20:16:46.390+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.saveAll]
2025-09-19T20:16:46.391+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [kr.co.pinup.storeimages.service.StoreImageService.createUploadImages]
2025-09-19T20:16:46.391+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-19T20:16:46.391+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(24846046<open>)]
2025-09-19T20:16:46.398+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.SQL : insert into store_operating_hour (created_at,days,end_time,start_time,store_id) values (?,?,?,?,?)
2025-09-19T20:16:46.398+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:TIMESTAMP) <- [2025-09-19T20:16:46.394673700]
2025-09-19T20:16:46.399+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [월]
2025-09-19T20:16:46.399+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (3:TIME) <- [20:00]
2025-09-19T20:16:46.400+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (4:TIME) <- [08:00]
2025-09-19T20:16:46.400+09:00 TRACE 5812 --- [pinup] [nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (5:BIGINT) <- [15]
2025-09-19T20:16:46.414+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-19T20:16:46.415+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] k.co.pinup.stores.service.StoreService : createStore storeImages=[kr.co.pinup.storeimages.StoreImage@3b006fd1]
2025-09-19T20:16:46.415+09:00 INFO 5812 --- [pinup] [nio-8080-exec-3] k.co.pinup.stores.service.StoreService : StoreService.createStore() end
2025-09-19T20:16:46.416+09:00 INFO 5812 --- [pinup] [nio-8080-exec-3] k.co.pinup.aop.QueryExecutionTimeAspect : joinPoint Signature: createStore, Execution time: 287 ms
2025-09-19T20:16:46.436+09:00 DEBUG 5812 --- [pinup] [nio-8080-exec-3] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-19T20:17:07.848+09:00 DEBUG 5812 --- [pinup] [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2025-09-19T20:17:07.849+09:00 DEBUG 5812 --- [pinup] [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
다수의 쿼리가 존재하지만 트랜잭션을 명시적으로 선언하지 않아, 각 쿼리는 개별적으로 실행되며 별도의 트랜잭션으로 처리되지 않습니다. 이 경우 각 작업이 독립적으로 수행되며, 실패한 작업만 롤백되고 전체 작업의 원자성이 보장되지 않습니다. 또한 매 쿼리마다 커밋이 발생하기 때문에 성능적으로도 오버헤드가 큽니다. 실행 시간이 약 287ms가 소요되고 있습니다.
@Transactional 선언 ✅
이번엔 createStore() 메서드에 @Transactional을 선언했습니다.
2025-09-19T20:28:06.278+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-19T20:28:06.410+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] k.c.p.s.controller.StoreApiController : createStore StoreRequest=StoreRequest[name=팝업 테스트2, description=팝업 테스트2, startDate=2025-09-19, endDate=2025-10-03, websiteUrl=, snsUrl=, thumbnailIndex=0, categoryId=1, locationId=17, operatingHours=[StoreOperatingHourRequest[days=월, startTime=10:00, endTime=20:00]]], images size=1
2025-09-19T20:28:06.417+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(49841951<open>)] for JPA transaction
2025-09-19T20:28:06.417+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [kr.co.pinup.stores.service.StoreService.createStore]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-09-19T20:28:06.417+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@3b34420c]
2025-09-19T20:28:06.417+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [kr.co.pinup.stores.service.StoreService.createStore]
2025-09-19T20:28:06.418+09:00 INFO 16528 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : StoreService.createStore() start
2025-09-19T20:28:06.418+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(49841951<open>)] for JPA transaction
2025-09-19T20:28:06.418+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-19T20:28:06.418+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:28:06.422+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : select sc1_0.id,sc1_0.created_at,sc1_0.name,sc1_0.updated_at from store_categories sc1_0 where sc1_0.id=?
2025-09-19T20:28:06.423+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
2025-09-19T20:28:06.426+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:28:06.427+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(49841951<open>)] for JPA transaction
2025-09-19T20:28:06.427+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-19T20:28:06.427+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:28:06.427+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : select l1_0.id,l1_0.address,l1_0.address_detail,l1_0.created_at,l1_0.latitude,l1_0.longitude,l1_0.name,l1_0.sido,l1_0.sigungu,l1_0.updated_at,l1_0.zonecode from locations l1_0 where l1_0.id=?
2025-09-19T20:28:06.427+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [17]
2025-09-19T20:28:06.430+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-19T20:28:06.431+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : createStore storeStatus=RESOLVED
2025-09-19T20:28:06.431+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(49841951<open>)] for JPA transaction
2025-09-19T20:28:06.431+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-19T20:28:06.432+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-19T20:28:06.448+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : insert into stores (category_id,created_at,description,end_date,is_deleted,location_id,name,sns_url,start_date,store_status,view_count,website_url) values (?,?,?,?,?,?,?,?,?,?,?,?)
2025-09-19T20:28:06.448+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
2025-09-19T20:28:06.448+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (2:TIMESTAMP) <- [2025-09-19T20:28:06.435505700]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (3:VARCHAR) <- [팝업 테스트2]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (4:DATE) <- [2025-10-03]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (5:BOOLEAN) <- [false]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (6:BIGINT) <- [17]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (7:VARCHAR) <- [팝업 테스트2]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (8:VARCHAR) <- []
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (9:DATE) <- [2025-09-19]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (10:VARCHAR) <- [RESOLVED]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (11:BIGINT) <- [0]
2025-09-19T20:28:06.449+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (12:VARCHAR) <- []
2025-09-19T20:28:06.454+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-19T20:28:06.455+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : createStore operatingHours=[kr.co.pinup.storeoperatinghour.StoreOperatingHour@20252c1c]
2025-09-19T20:28:06.456+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(49841951<open>)] for JPA transaction
2025-09-19T20:28:06.456+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-19T20:28:06.456+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [kr.co.pinup.storeimages.service.StoreImageService.createUploadImages]
2025-09-19T20:28:06.655+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(49841951<open>)] for JPA transaction
2025-09-19T20:28:06.655+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-19T20:28:06.655+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.saveAll]
2025-09-19T20:28:06.662+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : insert into store_images (created_at,image_url,is_deleted,is_thumbnail,store_id) values (?,?,?,?,?)
2025-09-19T20:28:06.662+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:TIMESTAMP) <- [2025-09-19T20:28:06.657864300]
2025-09-19T20:28:06.662+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [http://127.0.0.1:4566/pinup/store/aac24a9e-7450-4ea8-ba2a-ff3009a91707_%EC%8A%A4%ED%81%AC%EB%A6%B0%EC%83%B7%202025-09-19%20165540.png]
2025-09-19T20:28:06.663+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (3:BOOLEAN) <- [false]
2025-09-19T20:28:06.663+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (4:BOOLEAN) <- [true]
2025-09-19T20:28:06.663+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (5:BIGINT) <- [16]
2025-09-19T20:28:06.666+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.saveAll]
2025-09-19T20:28:06.666+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [kr.co.pinup.storeimages.service.StoreImageService.createUploadImages]
2025-09-19T20:28:06.666+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : createStore storeImages=[kr.co.pinup.storeimages.StoreImage@19f9217e]
2025-09-19T20:28:06.666+09:00 INFO 16528 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : StoreService.createStore() end
2025-09-19T20:28:06.670+09:00 INFO 16528 --- [pinup] [nio-8080-exec-8] k.co.pinup.aop.QueryExecutionTimeAspect : joinPoint Signature: createStore, Execution time: 253 ms
2025-09-19T20:28:06.670+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [kr.co.pinup.stores.service.StoreService.createStore]
2025-09-19T20:28:06.670+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-19T20:28:06.671+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(49841951<open>)]
2025-09-19T20:28:06.676+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : insert into store_operating_hour (created_at,days,end_time,start_time,store_id) values (?,?,?,?,?)
2025-09-19T20:28:06.677+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:TIMESTAMP) <- [2025-09-19T20:28:06.671587700]
2025-09-19T20:28:06.677+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [월]
2025-09-19T20:28:06.677+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (3:TIME) <- [20:00]
2025-09-19T20:28:06.679+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (4:TIME) <- [10:00]
2025-09-19T20:28:06.679+09:00 TRACE 16528 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (5:BIGINT) <- [16]
2025-09-19T20:28:06.703+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-19T20:28:06.724+09:00 DEBUG 16528 --- [pinup] [nio-8080-exec-8] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-19T20:28:24.523+09:00 DEBUG 16528 --- [pinup] [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2025-09-19T20:28:24.524+09:00 DEBUG 16528 --- [pinup] [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
이번엔 하나의 트랜잭션으로 묶여 모든 작업이 함께 처리됩니다. 이로 인해 하나라도 실패하면 전체 작업이 롤백되어 데이터 일관성이 유지됩니다. 실행 시간이 약 253ms로 소폭 단축되었으며, 트랜잭션 경계를 명확히 함으로써 안정성과 성능 모두를 개선할 수 있었습니다.
그러나 여전히 문제가 있습니다. 외부 API(S3 이미지 업로드)가 트랜잭션 안에서 수행되고 있기 때문에 트랜잭션 실행 시간이 길어지고, DB 커넥션 점유 시간도 함께 증가합니다. 또한 @Transactional이 선언된 메서드가 호출되면 그 즉시 DB 커넥션이 할당됩니다. 이러한 문제들을 해결하여 트랜잭션 실행 시간과 DB 커넥션 점유 시간을 단축시켜 보겠습니다.
트랜잭션 분리 전략
코드 삽입
2025-09-20T14:30:58.784+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-20T14:30:58.794+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] k.c.p.s.controller.StoreApiController : createStore StoreRequest=StoreRequest[name=팝업 테스트4, description=팝업 테스트4, startDate=2025-09-20, endDate=2025-10-04, websiteUrl=, snsUrl=, thumbnailIndex=0, categoryId=1, locationId=20, operatingHours=[StoreOperatingHourRequest[days=월, startTime=10:00, endTime=20:00]]], images size=1
2025-09-20T14:30:58.795+09:00 INFO 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : StoreService.createStore() start
2025-09-20T14:30:58.795+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : storeStatus: RESOLVED
2025-09-20T14:30:58.931+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1207756780<open>)] for JPA transaction
2025-09-20T14:30:58.931+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [kr.co.pinup.storecategories.service.StoreCategoryService.findCategoryById]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2025-09-20T14:30:58.931+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7c8310e5]
2025-09-20T14:30:58.931+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [kr.co.pinup.storecategories.service.StoreCategoryService.findCategoryById]
2025-09-20T14:30:58.931+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1207756780<open>)] for JPA transaction
2025-09-20T14:30:58.931+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-20T14:30:58.931+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-20T14:30:58.931+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : select sc1_0.id,sc1_0.created_at,sc1_0.name,sc1_0.updated_at from store_categories sc1_0 where sc1_0.id=?
2025-09-20T14:30:58.932+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
2025-09-20T14:30:58.934+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-20T14:30:58.934+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [kr.co.pinup.storecategories.service.StoreCategoryService.findCategoryById]
2025-09-20T14:30:58.934+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-20T14:30:58.934+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1207756780<open>)]
2025-09-20T14:30:58.937+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-20T14:30:58.937+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1207756780<open>)] for JPA transaction
2025-09-20T14:30:58.937+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [kr.co.pinup.locations.service.LocationService.getLocation]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2025-09-20T14:30:58.937+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@2749af50]
2025-09-20T14:30:58.937+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [kr.co.pinup.locations.service.LocationService.getLocation]
2025-09-20T14:30:58.937+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1207756780<open>)] for JPA transaction
2025-09-20T14:30:58.937+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-20T14:30:58.937+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-20T14:30:58.938+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : select l1_0.id,l1_0.address,l1_0.address_detail,l1_0.created_at,l1_0.latitude,l1_0.longitude,l1_0.name,l1_0.sido,l1_0.sigungu,l1_0.updated_at,l1_0.zonecode from locations l1_0 where l1_0.id=?
2025-09-20T14:30:58.938+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [20]
2025-09-20T14:30:58.941+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findById]
2025-09-20T14:30:58.941+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [kr.co.pinup.locations.service.LocationService.getLocation]
2025-09-20T14:30:58.941+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-20T14:30:58.941+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1207756780<open>)]
2025-09-20T14:30:58.942+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-20T14:30:58.943+09:00 INFO 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : StoreService.createStoreTransactional() start
2025-09-20T14:30:58.945+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : createStore operatingHours=[kr.co.pinup.storeoperatinghour.StoreOperatingHour@3eedeb42]
2025-09-20T14:30:58.945+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : createStore storeImages=[kr.co.pinup.storeimages.StoreImage@3c443fba]
2025-09-20T14:30:58.945+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1207756780<open>)] for JPA transaction
2025-09-20T14:30:58.945+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-09-20T14:30:58.945+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@9e7fd10]
2025-09-20T14:30:58.945+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-20T14:30:58.947+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : insert into stores (category_id,created_at,description,end_date,is_deleted,location_id,name,sns_url,start_date,store_status,view_count,website_url) values (?,?,?,?,?,?,?,?,?,?,?,?)
2025-09-20T14:30:58.947+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
2025-09-20T14:30:58.947+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (2:TIMESTAMP) <- [2025-09-20T14:30:58.946860800]
2025-09-20T14:30:58.947+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (3:VARCHAR) <- [팝업 테스트4]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (4:DATE) <- [2025-10-04]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (5:BOOLEAN) <- [false]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (6:BIGINT) <- [20]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (7:VARCHAR) <- [팝업 테스트4]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (8:VARCHAR) <- []
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (9:DATE) <- [2025-09-20]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (10:VARCHAR) <- [RESOLVED]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (11:BIGINT) <- [0]
2025-09-20T14:30:58.948+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (12:VARCHAR) <- []
2025-09-20T14:30:58.951+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : insert into store_operating_hour (created_at,days,end_time,start_time,store_id) values (?,?,?,?,?)
2025-09-20T14:30:58.952+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:TIMESTAMP) <- [2025-09-20T14:30:58.951835200]
2025-09-20T14:30:58.952+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [월]
2025-09-20T14:30:58.952+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (3:TIME) <- [20:00]
2025-09-20T14:30:58.952+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (4:TIME) <- [10:00]
2025-09-20T14:30:58.952+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (5:BIGINT) <- [19]
2025-09-20T14:30:58.955+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.SQL : insert into store_images (created_at,image_url,is_deleted,is_thumbnail,store_id) values (?,?,?,?,?)
2025-09-20T14:30:58.955+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (1:TIMESTAMP) <- [2025-09-20T14:30:58.955129]
2025-09-20T14:30:58.955+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [http://127.0.0.1:4566/pinup/store/51b2ff9c-e81f-4afd-ba44-2b847a69f5aa_authentic_cheeses_1.jpg]
2025-09-20T14:30:58.956+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (3:BOOLEAN) <- [false]
2025-09-20T14:30:58.956+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (4:BOOLEAN) <- [true]
2025-09-20T14:30:58.956+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] org.hibernate.orm.jdbc.bind : binding parameter (5:BIGINT) <- [19]
2025-09-20T14:30:58.958+09:00 TRACE 11064 --- [pinup] [nio-8080-exec-8] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-20T14:30:58.959+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-20T14:30:58.959+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1207756780<open>)]
2025-09-20T14:30:58.965+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-20T14:30:58.965+09:00 INFO 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.stores.service.StoreService : StoreService.createStoreTransactional() end
2025-09-20T14:30:58.965+09:00 INFO 11064 --- [pinup] [nio-8080-exec-8] k.co.pinup.aop.QueryExecutionTimeAspect : joinPoint Signature: createStore, Execution time: 170 ms
2025-09-20T14:30:58.967+09:00 DEBUG 11064 --- [pinup] [nio-8080-exec-8] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-20T14:31:06.609+09:00 DEBUG 11064 --- [pinup] [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2025-09-20T14:31:06.610+09:00 DEBUG 11064 --- [pinup] [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
이 문제를 해결하기 위해 트랜잭션을 다음과 같이 세분화했습니다.
- S3 업로드(IO)
- 조회 전용 트랜잭션
- 쓰기 전용 트랜잭션
외부 API 호출과 일반 비즈니스 로직을 트랜잭션 경계 밖에서 처리해 불필요한 커넥션 점유를 방지하고, 팝업스토어 카테고리 및 위치 주소 조회는 읽기 전용 트랜잭션으로 처리했습니다. 최종 저장 로직은 하나의 쓰기 트랜잭션으로 묶어 원자성과 일관성을 유지하면서 트랜잭션 경계를 최소화했습니다.
조회 전용(readOnly) 트랜잭션의 이점
조회용 트랜잭션과 쓰기용 트랜잭션을 분리하면 총 3개의 트랜잭션이 생성되지만, "조회 → 쓰기"의 명확한 흐름을 따르므로 안정성과 유지보수성이 향상됩니다. 특히 "@Transactional(readOnly = true)"를 선언하면 Hibernate는 해당 트랜잭션에서 데이터 변경이 없다고 간주하여 더티 체킹(Dirty Checking)과 플러시(flush) 등을 생략해 성능 오버헤드를 줄일 수 있습니다.
또한 이 어노테이션은 메서드가 오직 읽기 전용이라는 의도를 명확히 전달함으로써 코드 가독성과 안정성에도 기여할 수 있습니다.
DB 커넥션을 두 번 사용하는 구조이지만, findById와 같은 단순 조회는 리소스 소비가 크지 않기 때문에 안정성과 트랜잭션 효율화를 우선시했습니다.
DB Connection 획득 지연(Lazy) 전략
DB Connection 획득 지연 전략은 DB Connection 획득을 첫 SQL 실행 시점까지 지연시키는 전략입니다.
@Transactional를 선언한 메서드가 시작되면, Hibernate는 트랜잭션을 시작하면서 내부적으로 세션(Session)을 만들고, autoCommit 설정을 확인해야 하기 때문에 DB 커넥션(Connection)을 즉시 획득합니다.
하지만 트랜잭션의 첫 SQL 구문이 실행될 때까지 DB Connection을 연결할 필요가 없습니다. 만약 첫 SQL 구문이 실행 전 여러 비즈니스 로직이 실행되고 있는 상태에서 DB 커넥션을 획득하면 이 트랜잭션이 끝날 때까지 계속 잡고 있게 되고, 락까지 걸면 다른 트랜잭션들은 모두 오랜 시간 대기하게 됩니다. 그래서 첫 SQL 구문이 실행될 때 DB 커넥션을 획득하는 게 최적화 방법 중 하나입니다.
지연 전략 설정은 다음과 같습니다. Hibernate 5.2.10 이상인 경우만 적용이 가능합니다.
spring:
datasource:
hikari:
auto-commit: false
jpa:
properties:
hibernate:
connection:
provider_disables_autocommit: true
JDBC는 기본적으로 autoCommit = true 상태입니다. 이 상태에서는 SELECT, INSERT 등 SQL이 실행되면 자동으로 커밋됩니다. spring.datasource.hikari.auto-commit: false를 설정하면 HikariCP 커넥션 풀(Connection Pool)에서 커넥션을 생성하거나 풀에서 꺼낼 때, setAutoCommit(false)가 호출됩니다. 이 설정은 Spring 트랜잭션이나 Hibernate 여부와 상관없이, 모든 커넥션의 기본 상태를 autoCommit = false로 만듭니다.
autoCommit이 false이므로, 자동 커밋이 되지 않습니다. 따라서 사용 시 주의가 필요합니다. @Transactional이 선언되어 있으면 Spring이 자동으로 커밋 or 롤백을 진행하지만, 트랜잭션이 없이 직접 JDBC 사용한다면 명시적으로 커밋 or 롤백을 호출해야 합니다.
DB 커넥션 획득 지연 전략 설정의 핵심은 spring.jpa.properties.hibernate.connection.provider_disables_autocommit: true 설정입니다. Hibernate는 커넥션 provider(HikariCP 등)가 이미 적절하게 autoCommit을 설정한다고 믿고, getAutoCommit() 또는 setAutoCommit(false)를 더 이상 호출하지 않습니다.
이 설정이 있어야 Hibernate가 트랜잭션 시작 시 setAutoCommit(false) 호출을 생략하고, 즉시 커넥션을 획득하지 않고도 트랜잭션을 시작할 수 있게 됩니다.
이 설정이 필요한 이유?
이유는 퍼포먼스 최적화 때문입니다. 커넥션은 리소스가 비싸기 때문에, 불필요하게 가져오지 않도록 늦게 할당(Lazy Acquisition) 하는 게 효율적입니다. 즉, 실제 SQL이 필요할 때까지 커넥션을 지연해서 가져오는 것이 HikariCP + Hibernate의 전략입니다.
지연 전략 설정을 한 트랜잭션 흐름은 다음과 같습니다.(Hibernate + HikariCP + Spring 트랜잭션)
- 서비스 메서드에서 트랜잭션 시작(@Transactional)
- Hibernate가 내부적으로 Session 생성
- 아직 Connection은 사용하지 않음
- 실제로 SQL이 실행되지 않았기 때문
- userRepository.findAll() 호출
- Hibernate가 실제 쿼리를 DB에 날리려고 함
- 이때 HikariCP에서 Connection을 가져옴
- SQL 실행
- 트랜잭션 커밋
- 커넥션 반납
지연 전략 설정 예제
@Slf4j
@Service
@RequiredArgsConstructor
public class UserService {
private final UserRepository userRepository;
@Transactional
public void join(RequestJoin requestJoin) throws InterruptedException {
log.info("UserService.join requestJoin: {}", requestJoin);
User user = User.builder()
.name(requestJoin.name())
.email(requestJoin.email())
.build();
log.info("Waiting for a time-consuming task that does not need a database connection ...");
log.info("Thread.sleep start >>");
Thread.sleep(40_000);
log.info("Thread.sleep end >>");
log.info("Done, now query the database ...");
log.info("The database connection should be acquired now ...");
userRepository.save(user);
Thread.sleep(40_000);
log.info("userRepository.save() done.");
}
}
HikariPool 상태를 로그로 확인하기 위해 Thread.sleep(40_000)을 지정했습니다.
지연 전략 설정 ❌
2025-09-17T17:10:20.624+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-17T17:10:20.893+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] c.e.demo.controller.UserController : UserController.join requestJoin: RequestJoin[name=a, email=a@a.com]
2025-09-17T17:10:20.912+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(583032602<open>)] for JPA transaction
2025-09-17T17:10:20.913+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.example.demo.service.UserService.join]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-09-17T17:10:20.920+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@3b45f22]
2025-09-17T17:10:20.920+09:00 TRACE 259964 --- [demo] [nio-8080-exec-2] o.s.t.i.TransactionInterceptor : Getting transaction for [com.example.demo.service.UserService.join]
2025-09-17T17:10:20.921+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : UserService.join requestJoin: RequestJoin[name=a, email=a@a.com]
2025-09-17T17:10:20.921+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : Waiting for a time-consuming task that does not need a database connection ...
2025-09-17T17:10:20.921+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : Thread.sleep start >>
2025-09-17T17:10:33.608+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=9/10, active=1, waiting=0)
2025-09-17T17:10:33.609+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2025-09-17T17:11:00.922+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : Thread.sleep end >>
2025-09-17T17:11:00.922+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : Done, now query the database ...
2025-09-17T17:11:00.922+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : The database connection should be acquired now ...
2025-09-17T17:11:00.932+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(583032602<open>)] for JPA transaction
2025-09-17T17:11:00.932+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-17T17:11:00.932+09:00 TRACE 259964 --- [demo] [nio-8080-exec-2] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-17T17:11:01.016+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] org.hibernate.SQL : insert into users (email,name,id) values (?,?,default)
2025-09-17T17:11:01.039+09:00 TRACE 259964 --- [demo] [nio-8080-exec-2] org.hibernate.orm.jdbc.bind : binding parameter (1:VARCHAR) <- [a@a.com]
2025-09-17T17:11:01.040+09:00 TRACE 259964 --- [demo] [nio-8080-exec-2] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [a]
2025-09-17T17:11:01.082+09:00 TRACE 259964 --- [demo] [nio-8080-exec-2] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-17T17:11:03.610+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=9/10, active=1, waiting=0)
2025-09-17T17:11:03.610+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2025-09-17T17:11:33.610+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=9/10, active=1, waiting=0)
2025-09-17T17:11:33.611+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2025-09-17T17:11:41.082+09:00 INFO 259964 --- [demo] [nio-8080-exec-2] com.example.demo.service.UserService : userRepository.save() done.
2025-09-17T17:11:41.083+09:00 TRACE 259964 --- [demo] [nio-8080-exec-2] o.s.t.i.TransactionInterceptor : Completing transaction for [com.example.demo.service.UserService.join]
2025-09-17T17:11:41.083+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-17T17:11:41.085+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(583032602<open>)]
2025-09-17T17:11:41.110+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-17T17:11:41.168+09:00 DEBUG 259964 --- [demo] [nio-8080-exec-2] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-17T17:11:43.159+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn2: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:11:43.200+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn6: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:11:44.091+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn0: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:12:03.611+09:00 DEBUG 259964 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=10/10, active=0, waiting=0)
"sleep" 진행 중일 때 "HikariPool - 1 - Pool stats (total=10/10, idle=9/10, active=1, waiting=0)" active 활성 상태가 1로 증가된 것을 볼 수 있습니다. userRepository.save()인 SQL이 실행되기 전에 커넥션이 이미 획득된 상태입니다.
지연 전략 설정 ✅
2025-09-17T17:17:58.073+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-17T17:17:58.256+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] c.e.demo.controller.UserController : UserController.join requestJoin: RequestJoin[name=a, email=a@a.com]
2025-09-17T17:17:58.265+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1768973861<open>)] for JPA transaction
2025-09-17T17:17:58.267+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.example.demo.service.UserService.join]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-09-17T17:17:58.276+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@2c25302c]
2025-09-17T17:17:58.277+09:00 TRACE 264057 --- [demo] [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [com.example.demo.service.UserService.join]
2025-09-17T17:17:58.278+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : UserService.join requestJoin: RequestJoin[name=a, email=a@a.com]
2025-09-17T17:17:58.280+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : Waiting for a time-consuming task that does not need a database connection ...
2025-09-17T17:17:58.280+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : Thread.sleep start >>
2025-09-17T17:17:58.801+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn9: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:18:01.595+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=10/10, active=0, waiting=0)
2025-09-17T17:18:01.596+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2025-09-17T17:18:01.616+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn2: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:18:31.597+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=10/10, active=0, waiting=0)
2025-09-17T17:18:31.600+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2025-09-17T17:18:38.280+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : Thread.sleep end >>
2025-09-17T17:18:38.280+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : Done, now query the database ...
2025-09-17T17:18:38.281+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : The database connection should be acquired now ...
2025-09-17T17:18:38.285+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1768973861<open>)] for JPA transaction
2025-09-17T17:18:38.285+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
2025-09-17T17:18:38.285+09:00 TRACE 264057 --- [demo] [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-17T17:18:38.315+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] org.hibernate.SQL : insert into users (email,name,id) values (?,?,default)
2025-09-17T17:18:38.318+09:00 TRACE 264057 --- [demo] [nio-8080-exec-1] org.hibernate.orm.jdbc.bind : binding parameter (1:VARCHAR) <- [a@a.com]
2025-09-17T17:18:38.322+09:00 TRACE 264057 --- [demo] [nio-8080-exec-1] org.hibernate.orm.jdbc.bind : binding parameter (2:VARCHAR) <- [a]
2025-09-17T17:18:38.363+09:00 TRACE 264057 --- [demo] [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2025-09-17T17:19:01.602+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=9/10, active=1, waiting=0)
2025-09-17T17:19:01.603+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2025-09-17T17:19:16.823+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn1: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:19:18.364+09:00 INFO 264057 --- [demo] [nio-8080-exec-1] com.example.demo.service.UserService : userRepository.save() done.
2025-09-17T17:19:18.364+09:00 TRACE 264057 --- [demo] [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [com.example.demo.service.UserService.join]
2025-09-17T17:19:18.364+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2025-09-17T17:19:18.364+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1768973861<open>)]
2025-09-17T17:19:18.374+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2025-09-17T17:19:18.399+09:00 DEBUG 264057 --- [demo] [nio-8080-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2025-09-17T17:19:24.923+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn7: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:19:26.707+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - keepalive: connection conn6: url=jdbc:h2:mem:testdb user=SA is alive
2025-09-17T17:19:31.605+09:00 DEBUG 264057 --- [demo] [l-1:housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10/10, idle=10/10, active=0, waiting=0)
이번에는 "sleep" 진행 중일 때 "HikariPool - 1 - Pool stats (total=10/10, idle=10/10, active=0, waiting=0)" active 활성 상태가 0으로 커넥션을 아직 획득하지 않았고, userRepository.save()가 실행되면서 insert into users (email,name,id) values(?,?,default) SQL이 로그에 출력되고, "HikariPool - 1 - Pool stats (total=10/10, idle=9/10, active=1, waiting=0)" active 활성 상태가 1로 증가된 것을 볼 수 있습니다.
트랜잭션 격리 수준(Isolation Level)
프로젝트에서 데이터베이스는 PostgreSQL을 사용 중입니다. Isolation의 기본 값은 "Read Committed"입니다.
트랜잭션 격리 수준은 PostgreSQL에 접속해서 다음과 같이 확인할 수 있습니다.
select current_setting('transaction_isolation');show transaction_isolation;
"Read Committed" 격리 수준에서는 Non-repeatable Read, Phantom Read 등의 현상이 발생할 수 있습니다.
Non-repeatable Read, Phantom Read 현상은 같은 트랜잭션에서 여러 번 조회했을 때 결과가 달라지는데, 동일 트랜잭션 내에서 반복 조회가 없기 때문에 실제 비즈니스 로직에서는 영향이 거의 없습니다. 따라서 격리 수준을 높여 얻을 수 있는 이점보다, 불필요한 성능 저하 위험이 더 크다고 판단했습니다.
Lost Update 현상의 경우에는 트랜잭션이 동시에 같은 레코드를 수정하면서 마지막에 커밋한 데이터만 업데이트되고, 이전에 수정한 데이터는 사라지는 현상인데 저희 서비스에서는 등록, 수정 등이 관리자 혹은 작성한 사용자만 가능하기 때문에 여러 트랜잭션이 동시에 같은 레코드를 처리할 수 없기 때문에 발생하지 않는다고 생각했습니다.
그래서 테스트 코드로 발생하는 현상들을 재현하는 것으로 진행했습니다.
Non-repeatable Read 현상
@DisplayName("Read Committed level에서 Non-Repeatable read 현상 발생")
@Test
void readCommittedNonRepeatableRead() throws Exception {
// Arrange
final Long storeId = getStoreId();
CountDownLatch readLatch = new CountDownLatch(1);
CountDownLatch updateLatch = new CountDownLatch(1);
AtomicReference<StoreStatus> firstRead = new AtomicReference<>();
AtomicReference<StoreStatus> secondRead = new AtomicReference<>();
// Act
CompletableFuture<Void> reader = CompletableFuture.runAsync(() -> {
TransactionTemplate transaction1 = new TransactionTemplate(transactionManager);
transaction1.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
firstRead.set(store.getStoreStatus());
readLatch.countDown();
try {
updateLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
entityManager.refresh(store);
secondRead.set(store.getStoreStatus());
});
});
CompletableFuture<Void> updater = CompletableFuture.runAsync(() -> {
try {
readLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
TransactionTemplate transaction2 = new TransactionTemplate(transactionManager);
transaction2.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
store.updateStatus(DISMISSED);
storeRepository.save(store);
});
updateLatch.countDown();
});
reader.get();
updater.get();
// Assert
assertThat(firstRead.get()).isEqualTo(RESOLVED);
assertThat(secondRead.get()).isEqualTo(DISMISSED);
assertThat(firstRead.get()).isNotEqualTo(secondRead.get());
}
코드의 흐름은 다음과 같습니다.
- 비동기로 트랜잭션 1, 2가 실행되고, 트랜잭션 2 부분은 readLatch.await()로 대기시킵니다.
- 트랜잭션 1에서 storeId로 조회하고 상태 값을 firstRead(원자성을 보장하는 클래스)에 설정하고, 트랜잭션 2의 실행이 끝날 때까지 대기합니다.
- 트랜잭션 2에서 같은 storeId로 조회를 하고 상태를 변경합니다.
- 다시 트랜잭션 1이 시작되고, entityManager.refresh()로 1차 캐시를 무시하고 DB로부터 최신 상태를 다시 가져오게 합니다.
- 2번에서 조회한 값으로 상태를 secondRead에 설정합니다.
- firstRead, secondRead를 비교합니다.(조회된 결과 값이 달라진 것을 알 수 있습니다)
Non-repeatable Read 현상 방지
@DisplayName("Repeatable Read level에서 non-repeatable read 현상 방지")
@Test
void repeatableReadWithoutNonRepeatableRead() throws Exception {
// Arrange
final Long storeId = getStoreId();
CountDownLatch readLatch = new CountDownLatch(1);
CountDownLatch updateLatch = new CountDownLatch(1);
AtomicReference<StoreStatus> firstRead = new AtomicReference<>();
AtomicReference<StoreStatus> secondRead = new AtomicReference<>();
// Act
CompletableFuture<Void> reader = CompletableFuture.runAsync(() -> {
TransactionTemplate transaction1 = new TransactionTemplate(transactionManager);
transaction1.setIsolationLevel(TransactionDefinition.ISOLATION_REPEATABLE_READ);
transaction1.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
firstRead.set(store.getStoreStatus());
readLatch.countDown();
try {
updateLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
entityManager.refresh(store);
secondRead.set(store.getStoreStatus());
});
});
CompletableFuture<Void> updater = CompletableFuture.runAsync(() -> {
try {
readLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
TransactionTemplate transaction2 = new TransactionTemplate(transactionManager);
transaction2.setIsolationLevel(TransactionDefinition.ISOLATION_REPEATABLE_READ);
transaction2.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
store.updateStatus(DISMISSED);
storeRepository.save(store);
});
updateLatch.countDown();
});
reader.get();
updater.get();
// Assert
assertThat(firstRead.get()).isEqualTo(RESOLVED);
assertThat(secondRead.get()).isEqualTo(RESOLVED);
assertThat(firstRead.get()).isEqualTo(secondRead.get());
}
Non-repeatable Read 현상을 방지하기 위해 Isolation을 Read Committed에서 "Repeatable Read"로 둘 다 변경하고 이전 코드들은 그전과 같습니다. Non-repeatable Read 현상이 보장돼서 결과 값이 동일한 것을 알 수 있습니다.
방지하기 위해 격리 수준을 올리거나 낙관적 락(Optimistic Lock), 비관적 락(Pessimistic Lock) 등으로 방지할 수 있습니다.
Phantom Read 현상
@DisplayName("Read Committed level에서 Phantom Read 현상 재현")
@Test
void readCommittedPhantomRead() throws Exception {
// Arrange
final Location location = createLocation();
locationRepository.save(location);
final StoreCategory category = createCategory();
storeCategoryRepository.save(category);
storeRepository.save(createStore(
"Store1",
"Store Description1",
RESOLVED,
category,
location
));
CountDownLatch readLatch = new CountDownLatch(1);
CountDownLatch insertLatch = new CountDownLatch(1);
AtomicReference<List<Store>> firstRead = new AtomicReference<>();
AtomicReference<List<Store>> secondRead = new AtomicReference<>();
// Act
CompletableFuture<Void> reader = CompletableFuture.runAsync(() -> {
TransactionTemplate transaction1 = new TransactionTemplate(transactionManager);
transaction1.executeWithoutResult(status -> {
final List<Store> stores1 = storeRepository.findAll();
firstRead.set(stores1);
readLatch.countDown();
try {
insertLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
final List<Store> stores2 = storeRepository.findAll();
secondRead.set(stores2);
});
});
CompletableFuture<Void> writer = CompletableFuture.runAsync(() -> {
try {
readLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
TransactionTemplate transaction2 = new TransactionTemplate(transactionManager);
transaction2.executeWithoutResult(status -> {
storeRepository.save(createStore(
"Store2",
"Store Description2",
RESOLVED,
category,
location
));
});
insertLatch.countDown();
});
reader.get();
writer.get();
// Assert
assertThat(firstRead.get()).hasSize(1);
assertThat(secondRead.get()).hasSize(2);
}
흐름은 이전 코드와 비슷합니다. 이번엔 동일 트랜잭션 내에서 findAll()을 두 번 호출했을 때, 중간에 다른 트랜잭션이 새로운 레코드를 Insert 하여 두 번째 조회 시 추가된 데이터가 함께 조회되는 현상입니다.
Phantom Read 현상 방지
@DisplayName("Repeatable Read level에서 Phantom Read 현상 방지")
@Test
void repeatableReadWithoutPhantomRead() throws Exception {
// Arrange
final Location location = createLocation();
locationRepository.save(location);
final StoreCategory category = createCategory();
storeCategoryRepository.save(category);
storeRepository.save(createStore(
"Store1",
"Store Description1",
RESOLVED,
category,
location
));
CountDownLatch readLatch = new CountDownLatch(1);
CountDownLatch insertLatch = new CountDownLatch(1);
AtomicReference<List<Store>> firstRead = new AtomicReference<>();
AtomicReference<List<Store>> secondRead = new AtomicReference<>();
// Act
CompletableFuture<Void> reader = CompletableFuture.runAsync(() -> {
TransactionTemplate transaction1 = new TransactionTemplate(transactionManager);
transaction1.setIsolationLevel(TransactionDefinition.ISOLATION_REPEATABLE_READ);
transaction1.executeWithoutResult(status -> {
final List<Store> stores1 = storeRepository.findAll();
firstRead.set(stores1);
readLatch.countDown();
try {
insertLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
final List<Store> stores2 = storeRepository.findAll();
secondRead.set(stores2);
});
});
CompletableFuture<Void> writer = CompletableFuture.runAsync(() -> {
try {
readLatch.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
TransactionTemplate transaction2 = new TransactionTemplate(transactionManager);
transaction2.setIsolationLevel(TransactionDefinition.ISOLATION_REPEATABLE_READ);
transaction2.executeWithoutResult(status -> {
storeRepository.save(createStore(
"Store2",
"Store Description2",
RESOLVED,
category,
location
));
});
insertLatch.countDown();
});
reader.get();
writer.get();
// Assert
assertThat(firstRead.get()).hasSize(1);
assertThat(secondRead.get()).hasSize(1);
assertThat(firstRead.get().size()).isEqualTo(secondRead.get().size());
}
이번에도 마찬가지로 격리 수준을 Repeatable Read로 변경하고 이전 코드들은 그전과 같습니다. "Phantom Read" 현상은 일반적인 데이터베이스 이론에서는 Repeatable Read에서도 Phantom Read 현상이 발생할 수 있는 격리 수준이지만, PostgreSQL의 Repeatable Read는 실제로는 ANSI SQL 기준의 Serializable에 가깝습니다. MVCC(Multi-Version Concurrency Control)와 트랜잭션 스냅숏(Snapshot) 기반 처리 덕분에 트랜잭션 시작 시점의 스냅샷을 기반으로 일관된 데이터를 조회하기 때문에, 이후 Insert 된 데이터는 같은 트랜잭션 내에서는 볼 수 없습니다.
Lost Update 현상
@DisplayName("Read Committed level에서 Lost Update 현상 재현")
@Test
void readCommittedLostUpdate() throws Exception {
// Arrange
final Long storeId = getStoreId();
CountDownLatch updateLatch1 = new CountDownLatch(1);
CountDownLatch updateLatch2 = new CountDownLatch(1);
// Act
CompletableFuture<Void> future1 = CompletableFuture.runAsync(() -> {
TransactionTemplate transactionTemplate = new TransactionTemplate(transactionManager);
transactionTemplate.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
store.updateStatus(PENDING);
updateLatch1.countDown();
try {
updateLatch2.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
storeRepository.saveAndFlush(store);
});
});
CompletableFuture<Void> future2 = CompletableFuture.runAsync(() -> {
try {
updateLatch1.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
TransactionTemplate transactionTemplate = new TransactionTemplate(transactionManager);
transactionTemplate.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
store.updateStatus(DISMISSED);
storeRepository.saveAndFlush(store);
});
updateLatch2.countDown();
});
future1.get();
future2.get();
// Assert
final Store result = storeRepository.findById(storeId)
.orElseThrow();
assertThat(result.getStoreStatus()).isEqualTo(PENDING);
}
Lost Update는 두 트랜잭션이 동일한 레코드를 읽고 수정할 때, 마지막에 커밋한 트랜잭션이 이전 트랜잭션의 변경 내용을 덮어쓰는 문제입니다. 결과적으로 먼저 커밋한 수정 내용이 사라집니다.
Lost Update 현상 방지
/**
* TODO : Entity에 Version을 사용해 Lost Update 현상 방지 가능
* @Version
* private int version;
*/
@DisplayName("Read Committed level에서 Optimistic Lock 사용해 Lost Update 현상 방지")
@Test
void readCommittedOptimisticLockWithoutLostUpdate() throws Exception {
// Arrange
final Long storeId = getStoreId();
CountDownLatch updateLatch1 = new CountDownLatch(1);
CountDownLatch updateLatch2 = new CountDownLatch(1);
// Act
CompletableFuture<Void> future1 = CompletableFuture.runAsync(() -> {
TransactionTemplate transactionTemplate = new TransactionTemplate(transactionManager);
assertThatThrownBy(() ->
transactionTemplate.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
store.updateStatus(PENDING);
updateLatch1.countDown();
try {
updateLatch2.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
storeRepository.saveAndFlush(store);
})
).isInstanceOf(ObjectOptimisticLockingFailureException.class);
});
CompletableFuture<Void> future2 = CompletableFuture.runAsync(() -> {
try {
updateLatch1.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
TransactionTemplate transactionTemplate = new TransactionTemplate(transactionManager);
transactionTemplate.executeWithoutResult(status -> {
final Store store = storeRepository.findById(storeId)
.orElseThrow();
store.updateStatus(DISMISSED);
storeRepository.saveAndFlush(store);
});
updateLatch2.countDown();
});
future1.get();
future2.get();
// Assert
final Store result = storeRepository.findById(storeId)
.orElseThrow();
assertThat(result.getStoreStatus()).isEqualTo(DISMISSED);
}
낙관적 락(Optimistic Lock)은 버전 번호(@Version)를 이용해 데이터 충돌을 감지합니다. 다른 트랜잭션이 먼저 커밋하면 버전이 증가하고, 나중에 커밋하는 트랜잭션은 ObjectOptimisticLockingFailureException을 던져 롤백됩니다.
실무에서는 이 예외를 감지해 재시도 로직을 구현하거나, 비관적 락(Pessimistic Write)으로 대체하기도 합니다.
그다음은 이전 파트에서 진행한 쿼리 튜닝으로 성능 개선한 것에 이어 캐시를 적용해 조금 더 개선해 보도록 하겠습니다.
🔗 Reference
- Hibernate 공식 문서: DB Connection 지연 전략
- How to Delay Database Connection Acquisition in Hibernate (Spring Data)
- DATA JPA + Transaction 성능 최적화
'spring' 카테고리의 다른 글
| Spring Data JPA @Transactional 이해하기 (0) | 2025.09.22 |
|---|---|
| 애플리케이션 성능 개선 Part 1 (feat. 병목 현상, N+1, 인덱스) (0) | 2025.08.21 |
| Spring REST Docs API 문서화 (0) | 2025.05.09 |
| [Spring] 인터셉터(Interceptor) 적용 (0) | 2022.04.17 |
| JPA @MappedSuperclass (0) | 2022.03.07 |
