슬렉 에러 체널을 보던 중, 504 Gateway Timeout이 지속적으로 발생하는 API가 있어서 무슨 문제가 있나 살펴보았다. 처음에는 GET속성의 API에서 조회 쿼리가 오래 걸려서 발생하겠거니 생각했지만 POST API에서 발생하는 문제였다.
문제의 API는 사용자가 쿠폰코드를 등록하는 API였고 문제를 해결하는데 재밌는 사실을 알게 되어 글로 남기고자 한다.
우선 테이블 구조에 대해 간략하게 살펴보자.
다음과 같은 연관관계를 갖는 세 개의 테이블이 있다.
해당 API는 사용자가 APP에서 코드쿠폰을 입력하면 쿠폰함에 해당 쿠폰이 등록되는 기능을 하는 API이다. API 내에서는 5회 정도의 유효성검사 이후에 user_coupon, map_code_coupon_user_coupon에 데이터를 각각 한 건 insert하는 게 다이다.
근데 해당 API에서 insert 쿼리가 10000개 이상 발생하여 12초 정도 소요됐고 GateWay response Timeout 설정 값인 10초가 초과되어 API Timeout이 발생하였다.
쿼리 로그를 살펴보니 user_coupon에 데이터를 한 건 insert 한 후에 의도치 않게 아래와 같이 map_code_coupon_user_coupon테이블에 insert하려는 code_coupon_id와 동일한 데이터를 모두 select하는 쿼리가 추가로 나가고 있었다.
select
userlaundr0_.laundrygo_coupon_code_id as laundryg2_79_1_,
userlaundr0_.user_laundrygo_coupon_promotion_id as user_lau3_79_1_,
userlaundr1_.id as id1_130_0_,
userlaundr1_.created_datetime as created_2_130_0_,
userlaundr1_.created_user_id as created_3_130_0_,
userlaundr1_.created_user_role_type as created_4_130_0_,
userlaundr1_.modified_datetime as modified5_130_0_,
userlaundr1_.modified_user_id as modified6_130_0_,
userlaundr1_.modified_user_role_type as modified7_130_0_,
userlaundr1_.delete_yn as delete_y8_130_0_,
userlaundr1_.expiration_end_datetime as expirati9_130_0_,
userlaundr1_.expiration_start_datetime as expirat10_130_0_,
userlaundr1_.forfeit_yn as forfeit11_130_0_,
userlaundr1_.laundrygo_coupon_promotion_id as laundry14_130_0_,
userlaundr1_.status as status12_130_0_,
userlaundr1_.subscription_id as subscri15_130_0_,
userlaundr1_.user_id as user_id13_130_0_,
userlaundr1_.wash_id as wash_id16_130_0_
from
map_laundrygo_coupon_code_user_laundrygo_coupon_promotion userlaundr0_
inner join user_laundrygo_coupon_promotion userlaundr1_ on userlaundr0_.user_laundrygo_coupon_promotion_id = userlaundr1_.id
where
(userlaundr1_.delete_yn = 'N')
and userlaundr0_.laundrygo_coupon_code_id = ?
더 놀라운 사실은 이 select한 데이터들을 transaction 종료시점에 모두 delete하고 또 전부 단건으로 insert하고 있었다는 것이다.
delete 쿼리
delete from map_laundrygo_coupon_code_user_laundrygo_coupon_promotion where laundrygo_coupon_code_id=?
insert 쿼리
아래에 같은 insert 쿼리가 위의 select에서 조회한 데이터 개수만큼 나간다.
insert into map_laundrygo_coupon_code_user_laundrygo_coupon_promotion (laundrygo_coupon_code_id, user_laundrygo_coupon_promotion_id) values (111056, 5475414)
결론적으로 해당 map_code_coupon_user_coupon테이블에 해당 요청을 통해 insert되어야 할 code_coupon_id의 모든 데이터를 전부 조회한 후 삭제하고 다시 넣고 있다. 해당 에러상황은 10700개 정도의 데이터를 전부 삭제하고 단건으로 다시 전부 insert하고 있어 응답시간이 약 12초 정도걸리고 있었다.
ex) 데이터가 10만 건이면 10만 건 조회 -> 모두 삭제 -> 10만 건을 단건으로 각각 insert
왜 다음과 같은 의도치 않은 쿼리들이 나가고 있을까?
문제는 JPA연관관계 설정에 있었다. 현재 ORM으로 Spring JPA를 사용하고 있다.
아래와 같이 code_coupon Entity에 user_coupon과 @ManyToMany 연관관계를 맺고 있다. 이렇게 설정해 두면 map_code_coupon_user_coupon에 따로 데이터를 save하는 로직이 없어도 user_coupon이 save되는 시점에 자동으로 map_code_coupon_user_coupon에 데이터가 save된다.
@ManyToMany
@JoinTable(name = "map_code_coupon_user_coupon",
joinColumns = @JoinColumn(name = "code_coupon_id"),
inverseJoinColumns = @JoinColumn(name = "user_coupon_id"))
private List<UserCoupon> userCoupons = new ArrayList<>();
하지만 자동으로 save가 된다는 이점이 있지만 위처럼 의도치 않은 쿼리가 발생하는 치명적인 단점이 존재한다.
결론적으로, @ManyToMany 연관관계 매핑을 제거하고 map_code_coupon_user_coupon를 직접 save하는 로직을 추가하여 해결하였다.
final MapCodecouponUserCoupon newMapCodecouponUserCoupon = MapCodecouponUserCoupon.create(codeCoupon, userCoupon);
mapCodecouponUserCouponRepository.save(newMapCodecouponUserCoupon);
수정후, 확인해보니 의도치 않은 불필요한 쿼리들이 더이상 나가지 않고 있었고 기존 12초 이상이 걸리던 API가 평균 72ms로 끝나는 것을 확인하였다.