Search

Lock으로 DeadLock과 맞서 싸우기

 사건의 발단

매일 12시 30분 커뮤니티의 인기 게시글에 대한 App Push를 발송하는 Job이 존재했습니다.
App Push가 발송되면 특정 게시글에 트래픽이 몰렸고 API 서버의 에러 알림으로 슬랙 채널이 계속 울렸습니다.
LockAcquisitionException 이 원인이라고 하지만 정확한 부검을 위해 미리 구축해둔 모니터링 툴들을 확인해보았습니다.

 원인 분석

Grafana의 APM Dashboard 확인

가장 먼저 Grafana로 API 서버의 대시보드를 확인하였습니다.
Tomcat과 HikariCP를 확인해보니 12시 30분부터 DB 트랜잭션 지연으로 인해 커넥션 풀과 스레드 풀이 Pending되는걸 확인할 수 있었습니다.

Pinpoint의 Transaction List와 Call Tree 확인

요청별로 좀 더 자세하게 확인하기 위해 Pinpoint를 확인하였습니다.
언뜻보더라도 12시 30분부터 응답 시간이 30초가 넘어가면서 timeout이 된 요청들이 많이 보였습니다.
자세한 Call Tree에선 HikariCP가 DB의 timeout으로 인해 커넥션을 획득할 수 없다는 메시지를 출력한걸 확인할 수 있습니다.

Test Code 작성

@Test @DisplayName("DeadLock Test") void DeadLock_Test() { int numberOfThreads = 10; ExecutorService executorService = Executors.newFixedThreadPool(numberOfThreads); CountDownLatch latch = new CountDownLatch(numberOfThreads); for (int i = 0; i < numberOfThreads; i++) { executorService.execute(() -> { webTestClient.post().uri(uriBuilder -> uriBuilder.path("/v1/jds/{jdId}/views").build(1)) .accept(MediaType.APPLICATION_JSON) .exchange(); }); latch.countDown(); } latch.await(); }
Java
복사
앞서 확인한 모니터링으로 DeadLock이 아닐까라는 의심을 하게 되었습니다.
그리고 좀 더 정확한 부검과 추후 해결을 위한 테스트 코드를 위처럼 작성하였습니다.
간단하게 정해진 갯수의 스레드를 이용해 멀티 스레드로 조회수 증가 API를 호출하는 코드입니다.

SQL General Log 분석

public void addView(HttpServletRequest request, Long jdId) { String token = authenticationProvider.resolveAccessToken(request); Jd jd = Optional.ofNullable(jdRepository.findJdById(jdId)).orElseThrow(() -> new CustomException(ErrorCode.BLANK_JD)); if (token != null) { Long userId = authenticationProvider.getId(token); User user = Optional.ofNullable(userRepository.findById(userId)).orElseThrow(() -> new CustomException(ErrorCode.BLANK_MEMBER)); List<JdView> jdViews = jdRepository.findJdViewsById(user.getId(), jd.getId()); if (!jdViews.isEmpty() && jdViews.stream().anyMatch(jv -> jv.getCreatedTime().toLocalDate().equals(LocalDate.now()))) { return; } JdView jdView = JdView.builder().user(user).jd(jd).build(); jd.getJdViews().add(jdView); jd.increaseView(); } else { jd.increaseView(); } }
Java
복사
서비스에서의 현재 조회수 증가 로직은 위 코드와 같습니다.
1.
먼저 Entity가 존재하는지 확인합니다.
2.
회원일 경우 같은 날의 조회 기록을 확인하여 없다면 view 테이블에 INSERT하고 view 컬럼을 +1 해줍니다.
3.
비회원일 경우 INSERT 없이 view 컬럼만을 +1 합니다.
2023-10-30T11:21:21.591772Z 15621 Query SET autocommit=0 2023-10-30T11:21:21.592062Z 15619 Query SET autocommit=0 2023-10-30T11:21:21.592245Z 15617 Query SET autocommit=0 2023-10-30T11:21:21.594816Z 15620 Query SET autocommit=0 2023-10-30T11:21:21.594976Z 15615 Query SET autocommit=0 2023-10-30T11:21:21.596933Z 15622 Query SET autocommit=0 2023-10-30T11:21:21.591726Z 15616 Query SET autocommit=0 2023-10-30T11:21:21.597993Z 15624 Query SET autocommit=0 2023-10-30T11:21:21.598871Z 15620 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.599545Z 15621 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.601976Z 15617 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.602458Z 15615 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.604425Z 15619 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.605504Z 15622 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.605802Z 15616 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.598008Z 15623 Query SET autocommit=0 2023-10-30T11:21:21.609969Z 15620 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=2 2023-10-30T11:21:21.610244Z 15624 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.611542Z 15621 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=9 2023-10-30T11:21:21.613589Z 15616 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=6 2023-10-30T11:21:21.615588Z 15621 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=9 and jdview0_.jd_id=1 2023-10-30T11:21:21.616268Z 15624 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=1 2023-10-30T11:21:21.612360Z 15617 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=3 2023-10-30T11:21:21.618357Z 15620 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=2 and jdview0_.jd_id=1 2023-10-30T11:21:21.618476Z 15616 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=6 and jdview0_.jd_id=1 2023-10-30T11:21:21.613089Z 15615 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=5 2023-10-30T11:21:21.613155Z 15619 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=4 2023-10-30T11:21:21.613218Z 15622 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=10 2023-10-30T11:21:21.613306Z 15623 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.621647Z 15624 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=1 and jdview0_.jd_id=1 2023-10-30T11:21:21.591750Z 15618 Query SET autocommit=0 2023-10-30T11:21:21.626860Z 15623 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=7 2023-10-30T11:21:21.627169Z 15622 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=10 and jdview0_.jd_id=1 2023-10-30T11:21:21.627978Z 15615 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=5 and jdview0_.jd_id=1 2023-10-30T11:21:21.629000Z 15618 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 2023-10-30T11:21:21.628496Z 15617 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=3 and jdview0_.jd_id=1 2023-10-30T11:21:21.630143Z 15623 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=7 and jdview0_.jd_id=1 2023-10-30T11:21:21.631280Z 15619 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=4 and jdview0_.jd_id=1 2023-10-30T11:21:21.631949Z 15618 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=8 2023-10-30T11:21:21.633646Z 15618 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=8 and jdview0_.jd_id=1 2023-10-30T11:21:21.640461Z 15616 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.628332', 1, 6) 2023-10-30T11:21:21.640978Z 15620 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.628231', 1, 2) 2023-10-30T11:21:21.641216Z 15624 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.628231', 1, 1) 2023-10-30T11:21:21.641349Z 15615 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.630003', 1, 5) 2023-10-30T11:21:21.642283Z 15622 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.630045', 1, 10) 2023-10-30T11:21:21.643509Z 15618 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.635195', 1, 8) 2023-10-30T11:21:21.645028Z 15619 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.632597', 1, 4) 2023-10-30T11:21:21.645319Z 15621 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.628295', 1, 9) 2023-10-30T11:21:21.645345Z 15623 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.63214', 1, 7) 2023-10-30T11:21:21.645362Z 15617 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:21:21.632014', 1, 3) 2023-10-30T11:21:21.650422Z 15615 Query update jd set updated_time='2023-10-30 20:21:21.644476', view=2 where id=1 2023-10-30T11:21:21.650496Z 15617 Query update jd set updated_time='2023-10-30 20:21:21.647653', view=2 where id=1 2023-10-30T11:21:21.650586Z 15616 Query update jd set updated_time='2023-10-30 20:21:21.644438', view=2 where id=1 2023-10-30T11:21:21.650625Z 15619 Query update jd set updated_time='2023-10-30 20:21:21.646692', view=2 where id=1 2023-10-30T11:21:21.650661Z 15620 Query update jd set updated_time='2023-10-30 20:21:21.644367', view=2 where id=1 2023-10-30T11:21:21.650687Z 15624 Query update jd set updated_time='2023-10-30 20:21:21.644732', view=2 where id=1 2023-10-30T11:21:21.650407Z 15622 Query update jd set updated_time='2023-10-30 20:21:21.644367', view=2 where id=1 2023-10-30T11:21:21.650740Z 15621 Query update jd set updated_time='2023-10-30 20:21:21.647052', view=2 where id=1 2023-10-30T11:21:21.650774Z 15623 Query update jd set updated_time='2023-10-30 20:21:21.647289', view=2 where id=1 2023-10-30T11:21:21.650792Z 15618 Query update jd set updated_time='2023-10-30 20:21:21.645342', view=2 where id=1 2023-10-30T11:21:21.654707Z 15615 Query commit 2023-10-30T11:21:21.655151Z 15615 Query SET autocommit=1 2023-10-30T11:21:21.661865Z 15621 Query rollback 2023-10-30T11:21:21.661912Z 15622 Query rollback 2023-10-30T11:21:21.661972Z 15617 Query rollback 2023-10-30T11:21:21.661889Z 15623 Query rollback 2023-10-30T11:21:21.661889Z 15618 Query rollback 2023-10-30T11:21:21.661907Z 15620 Query rollback 2023-10-30T11:21:21.662142Z 15621 Query SET autocommit=1 2023-10-30T11:21:21.661917Z 15616 Query rollback 2023-10-30T11:21:21.661865Z 15619 Query rollback 2023-10-30T11:21:21.661865Z 15624 Query rollback 2023-10-30T11:21:21.662209Z 15623 Query SET autocommit=1 2023-10-30T11:21:21.662149Z 15622 Query SET autocommit=1 2023-10-30T11:21:21.662163Z 15617 Query SET autocommit=1 2023-10-30T11:21:21.662441Z 15620 Query SET autocommit=1 2023-10-30T11:21:21.662199Z 15618 Query SET autocommit=1 2023-10-30T11:21:21.662477Z 15616 Query SET autocommit=1 2023-10-30T11:21:21.662665Z 15624 Query SET autocommit=1 2023-10-30T11:21:21.662686Z 15619 Query SET autocommit=1
Plain Text
복사
작성한 테스트 코드를 실행하면 위 로직대로 SELECT, INSERT, UPDATE가 순차적으로 발생하는걸 볼 수 있습니다.
그렇지만 Race Condition 상황에서 제일 먼저 도착한 트랜잭션을 제외한 나머지 트랜잭션은 전부 Rollback된걸 확인할 수 있습니다.
이 로그로 2가지 문제점을 확인할 수 있었습니다.
1.
모든 트랜잭션이 동시에 SELECT를 하여 같은 값을 읽기 때문에 모두 동일한 값으로 UPDATE하는 것
2.
모든 트랜잭션이 1초 미만의 시간에 모든 요청을 동시에 처리하고 있는 상황이기 때문에 DeadLock에 의한 Rollback이 발생하는 것

Server Log 분석

2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-6] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-5] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 WARN 74107 --- [ool-6-thread-10] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-2] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-5] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-7] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-3] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-2] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-7] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-9] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-3] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 ERROR 74107 --- [ool-6-thread-10] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-4] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-9] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 WARN 74107 --- [pool-6-thread-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-4] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-6] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.875 ERROR 74107 --- [pool-6-thread-1] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-4] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-3] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-9] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [ool-6-thread-10] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-5] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-2] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-1] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-7] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements 2023-10-30 19:54:40.876 INFO 74107 --- [pool-6-thread-6] o.h.e.j.b.internal.AbstractBatchImpl : HHH000010: On release of batch it still contained JDBC statements Exception in thread "pool-6-thread-5" org.springframework.web.reactive.function.client.WebClientRequestException: Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement; nested exception is org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141) at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:55) at reactor.core.publisher.Mono.subscribe(Mono.java:4397) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134) at reactor.core.publisher.Operators.error(Operators.java:198) at reactor.core.publisher.MonoError.subscribe(MonoError.java:53) at reactor.core.publisher.Mono.subscribe(Mono.java:4397) at reactor.core.publisher.Mono.block(Mono.java:1730) at org.springframework.test.web.reactive.server.DefaultWebTestClient$DefaultRequestBodyUriSpec.exchange(DefaultWebTestClient.java:361) at com.gocho.user.jd.JdViewSaveTest.lambda$동시성_이슈_테스트$1(JdViewSaveTest.java:65) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833) Suppressed: java.lang.Exception: #block terminated with an error at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:139) at reactor.core.publisher.Mono.block(Mono.java:1731) ... 5 more Caused by: org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909) at javax.servlet.http.HttpServlet.service(HttpServlet.java:681) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) at org.springframework.test.web.servlet.TestDispatcherServlet.service(TestDispatcherServlet.java:72) at javax.servlet.http.HttpServlet.service(HttpServlet.java:764) at org.springframework.mock.web.MockFilterChain$ServletFilterProxy.doFilter(MockFilterChain.java:167) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at com.gocho.core.slack.HttpServletRequestWrapper.doFilterInternal(HttpServletRequestWrapper.java:23) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at com.gocho.core.filter.SignedUrlFilter.doFilter(SignedUrlFilter.java:57) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:111) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:111) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.web.servlet.resource.ResourceUrlEncodingFilter.doFilter(ResourceUrlEncodingFilter.java:67) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.boot.web.servlet.filter.ErrorPageSecurityFilter.doFilter(ErrorPageSecurityFilter.java:80) at org.springframework.boot.web.servlet.filter.ErrorPageSecurityFilter.doFilter(ErrorPageSecurityFilter.java:70) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:166) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at com.gocho.core.filter.CustomBasicAuthenticationFilter.doFilterInternal(CustomBasicAuthenticationFilter.java:49) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at com.gocho.core.filter.JwtAuthenticationFilter.doFilterInternal(JwtAuthenticationFilter.java:81) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:91) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90) at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:112) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:82) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211) at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:134) at org.springframework.test.web.servlet.MockMvc.perform(MockMvc.java:199) at org.springframework.test.web.servlet.client.MockMvcHttpConnector.connect(MockMvcHttpConnector.java:98) at org.springframework.test.web.reactive.server.WiretapConnector.connect(WiretapConnector.java:71) at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:103) ... 5 more Caused by: org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:267) at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:233) at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:566) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708) at com.gocho.user.service.JdService$$EnhancerBySpringCGLIB$$e57f3d7c.addView(<generated>) at com.gocho.user.controller.v1.JdControllerV1.addView(JdControllerV1.java:174) at com.gocho.user.controller.v1.JdControllerV1$$FastClassBySpringCGLIB$$949fdf5c.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708) at com.gocho.user.controller.v1.JdControllerV1$$EnhancerBySpringCGLIB$$d47e32df.addView(<generated>) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1070) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ... 94 more Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement at org.hibernate.dialect.MySQLDialect$3.convert(MySQLDialect.java:562) at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:37) at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:200) at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:46) at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3571) at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3438) at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3852) at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:202) at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604) at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:721) at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344) at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107) at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1407) at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:489) at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3290) at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2425) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:449) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281) at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101) at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:562) ... 127 more Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123) at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916) at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061) at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1009) at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1320) at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:994) at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197) ... 149 more ...이하 생략
Plain Text
복사
Race Condition에서 가장 먼저 도착한 Thread-8을 제외한 나머지 스레드에서 아래와 같은 에러를 확인할 수 있습니다.
SQL Error: 1213, SQLState: 40001
Deadlock found when trying to get lock; try restarting transaction
현재 DB는 MySQL innodb 엔진을 사용하고 있고 해결을 위해서 각 상황에 따른 락 상태를 확인해보겠습니다.

 MySQL의 Lock

각 SQL마다 Lock 상태

•
SELECT
◦
Table : None
◦
Record : None
•
SELECT ~ for share (S-LOCK)
◦
Table : IS (Intention Shared Lock)
◦
Record : S (Shared Lock)
•
SELECT ~ for update (X-LOCK)
◦
Table : IX (Intention Exclusive Lock)
◦
Record : X (Exclusive Lock)
•
INSERT
◦
Table : IS (Intention Shared Lock)
◦
Record : S (Shared Lock)
•
UPDATE
◦
Table : IX (Intention Exclusive Lock)
◦
Record : X (Exclusive Lock)

Lock의 종류

•
Intention Lock (의도 잠금)
◦
Table Level Lock
◦
해당 테이블 Row 중 나중에 Row Level Lock이 걸릴 것이라는 걸 미리 알려주기 위해 사용합니다.
•
Shared Lock (공유 잠금)
◦
Row Level Lock
◦
특정 Row를 읽을 때 사용되고 다른 말로 Read Lock 이라고도 합니다.
◦
다른 트랜잭션이 해당 Row에 대해 베타 락은 획득이 불가능하지만, 공유 락은 획득이 가능합니다.
•
Exclusive Lock (베타 잠금)
◦
Row Level Lock
◦
특정 Row를 변경 혹은 삭제하고자 할 때 사용되고 다른 말로 Write Lock 이라고도 합니다.
◦
다른 트랜잭션이 해당 Row에 대해 공유 락 / 베타 락 모두 획득하지 못하고 대기하게 됩니다.

Lock별 호환 표

 Optimistic Lock vs Pessimistic Lock

기존에 Lock이 걸리지 않는 일반 SELECT를 사용했기 때문에 동시에 같은 값의 view를 조회하는 문제가 있었고
트랜잭션끼리 Race Condition 상태가 되어서 커넥션 풀과 스레드 풀이 매말랐던 문제가 있었던 것이었습니다.
MySQL innoDB 엔진에는 트랜잭션간 Lock 획득으로 인한 대기가 존재합니다.
SHOW VARIABLES LIKE 'innodb_lock_wait_timeout'; 를 통해 확인이 가능하며 기본값은 50초입니다.
그러면 위에 General Log에선 왜 1개의 트랜잭션을 제외한 나머지 트랜잭션들은 동시에 rollback이 된걸까요?
그 답은 innoDB 엔진의 데드락 탐지 및 처리 메커니즘에 있었습니다.
innoDB는 명시적으로 Lock이 선언되어있지 않아서 DeadLock이 발생할거라 미리 예측하고 대기도 없이 즉각 Rollback을 시킨 것입니다.
이제 답을 알았으니 명시적으로 Lock을 걸어주어 해결해보겠습니다.

Optimistic Lock(낙관적 락)이란?

낙관적 락은 충돌이 거의 발생하지 않을 것이라고 가정하고, 충돌이 발생한 경우에 대비하는 방식입니다.
JPA에선 @Version을 통해 구현할 수 있으며 version 컬럼뿐만이 아닌 timestamp, hashcode를 사용할 수 있습니다.
낙관적 락의 특징으로는 충돌 발생확률이 낮고, 지속적인 락으로 인한 성능저하를 막을 수 있지만 충돌 발생 시 처리해야하는 외부 요인이 존재한다는 것입니다.

Pessimistic Lock(비관적 락)이란?

비관적 락은 충돌이 발생할 확률이 높다고 가정하여, 실제로 데이터에 액세스 하기 전에 먼저 락을 걸어 충돌을 예방하는 방식입니다.
비관적 락은 JPA에서 제공하는 LockModeType을 사용하여 구현할 수 있습니다.
비관적 락의 특징으로는 충돌 발생을 미연에 방지하고 데이터의 일관성을 유지할 수 있지만 동시 처리 성능이 저하될 수 있고 DeadLock이 발생할 수 있다는 것입니다.

JPA의 LockModeType

낙관적 락
OPTIMISTIC
낙관적 락을 사용한다.
OPTIMISTIC_FORCE_INCREMENT
낙관적 락 + 버전정보를 강제로 증가 시킨다.
비관적 락
PESSIMISTIC_READ
읽기 잠금을 사용한다.
PESSIMISTIC_WRITE
쓰기 잠금을 사용한다.
PESSIMISTIC_FORCE_INCREMENT
비관적 락 + 버전정보를 강제로 증가시킨다.
기타
NONE
READ
OPTIMISTIC과 같다.
WRITE
OPTIMISTIC_FORCE_INCREMENT 와 같다.

코드 수정

public Jd findJdByIdWithPessimisticLock(Long jdId) { return em.find(Jd.class, jdId, LockModeType.PESSIMISTIC_WRITE); }
Java
복사
기존 Jd를 조회하는 부분에 LockModeType.PESSIMISTIC_WRITE를 추가합니다.
그러면 이제 SELECT ~ for update를 통해 조회하며 명시적으로 Record에 X-LOCK을 걸게 됩니다.

 확인

#!/bin/bash for i in {1..50}; do curl -X POST http://localhost:8080/v1/jds/1/views & done
Plain Text
복사
작성해둔 테스트 코드가 아닌 실제 API 요청과 비슷하게 하기 위해 curl을 이용한 테스트를 진행하였습니다.
for문을 통해 조회수 증가 API를 호출하는 curl을 background process로 여러 번 실행시키는 쉘 스크립트를 작성 후 실행해보았습니다.
2023-10-30T11:13:50.541532Z 15594 Query SET autocommit=0 2023-10-30T11:13:50.545169Z 15594 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.545845Z 15589 Query SET autocommit=0 2023-10-30T11:13:50.541391Z 15585 Query SET autocommit=0 2023-10-30T11:13:50.547087Z 15587 Query SET autocommit=0 2023-10-30T11:13:50.547282Z 15590 Query SET autocommit=0 2023-10-30T11:13:50.547573Z 15591 Query SET autocommit=0 2023-10-30T11:13:50.547734Z 15593 Query SET autocommit=0 2023-10-30T11:13:50.547763Z 15592 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.549741Z 15594 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=10 2023-10-30T11:13:50.551451Z 15586 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.547763Z 15588 Query SET autocommit=0 2023-10-30T11:13:50.551636Z 15593 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.551661Z 15591 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.551866Z 15589 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.551886Z 15590 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.552028Z 15585 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.551661Z 15587 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.553001Z 15588 Query select jd0_.id as id1_13_0_, jd0_.created_time as created_2_13_0_, jd0_.updated_time as updated_3_13_0_, jd0_.apply_document as apply_do4_13_0_, jd0_.apply_email as apply_em5_13_0_, jd0_.apply_etc as apply_et6_13_0_, jd0_.apply_link as apply_li7_13_0_, jd0_.apply_process as apply_pr8_13_0_, jd0_.bookmark as bookmark9_13_0_, jd0_.click as click10_13_0_, jd0_.college as college11_13_0_, jd0_.company_id as company37_13_0_, jd0_.contract_type as contrac12_13_0_, jd0_.conversion_rate as convers13_13_0_, jd0_.cut as cut14_13_0_, jd0_.end_time as end_tim15_13_0_, jd0_.highschool as highsch16_13_0_, jd0_.hire_number as hire_nu17_13_0_, jd0_.is_direct as is_dire18_13_0_, jd0_.is_undefined as is_unde19_13_0_, jd0_.uploader_id as uploade38_13_0_, jd0_.pay as pay20_13_0_, jd0_.place_etc as place_e21_13_0_, jd0_.preferred_certification as preferr22_13_0_, jd0_.preferred_etc as preferr23_13_0_, jd0_.required_etc as require24_13_0_, jd0_.required_experience as require25_13_0_, jd0_.required_max_year as require26_13_0_, jd0_.required_min_year as require27_13_0_, jd0_.shift as shift28_13_0_, jd0_.start_time as start_t29_13_0_, jd0_.status as status30_13_0_, jd0_.task_description as task_de31_13_0_, jd0_.task_main as task_ma32_13_0_, jd0_.task_sub as task_su33_13_0_, jd0_.title as title34_13_0_, jd0_.university as univers35_13_0_, jd0_.view as view36_13_0_ from jd jd0_ where jd0_.id=1 for update 2023-10-30T11:13:50.553118Z 15594 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=10 and jdview0_.jd_id=1 2023-10-30T11:13:50.571983Z 15594 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.563542', 1, 10) 2023-10-30T11:13:50.580133Z 15594 Query update jd set updated_time='2023-10-30 20:13:50.575108', view=2 where id=1 2023-10-30T11:13:50.598704Z 15594 Query commit 2023-10-30T11:13:50.600000Z 15594 Query SET autocommit=1 2023-10-30T11:13:50.602603Z 15592 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=7 2023-10-30T11:13:50.604835Z 15592 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=7 and jdview0_.jd_id=1 2023-10-30T11:13:50.606765Z 15592 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.606223', 1, 7) 2023-10-30T11:13:50.608342Z 15592 Query update jd set updated_time='2023-10-30 20:13:50.607581', view=3 where id=1 2023-10-30T11:13:50.609175Z 15592 Query commit 2023-10-30T11:13:50.610742Z 15592 Query SET autocommit=1 2023-10-30T11:13:50.611888Z 15586 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=3 2023-10-30T11:13:50.614708Z 15586 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=3 and jdview0_.jd_id=1 2023-10-30T11:13:50.616560Z 15586 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.615913', 1, 3) 2023-10-30T11:13:50.617864Z 15586 Query update jd set updated_time='2023-10-30 20:13:50.617378', view=4 where id=1 2023-10-30T11:13:50.619364Z 15586 Query commit 2023-10-30T11:13:50.620276Z 15586 Query SET autocommit=1 2023-10-30T11:13:50.621998Z 15591 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=2 2023-10-30T11:13:50.624038Z 15591 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=2 and jdview0_.jd_id=1 2023-10-30T11:13:50.626527Z 15591 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.626011', 1, 2) 2023-10-30T11:13:50.627855Z 15591 Query update jd set updated_time='2023-10-30 20:13:50.627302', view=5 where id=1 2023-10-30T11:13:50.628420Z 15591 Query commit 2023-10-30T11:13:50.628979Z 15591 Query SET autocommit=1 2023-10-30T11:13:50.630567Z 15589 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=4 2023-10-30T11:13:50.632543Z 15589 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=4 and jdview0_.jd_id=1 2023-10-30T11:13:50.634402Z 15589 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.633812', 1, 4) 2023-10-30T11:13:50.635867Z 15589 Query update jd set updated_time='2023-10-30 20:13:50.635177', view=6 where id=1 2023-10-30T11:13:50.641157Z 15589 Query commit 2023-10-30T11:13:50.641809Z 15589 Query SET autocommit=1 2023-10-30T11:13:50.643427Z 15593 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=9 2023-10-30T11:13:50.645112Z 15593 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=9 and jdview0_.jd_id=1 2023-10-30T11:13:50.646957Z 15593 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.64645', 1, 9) 2023-10-30T11:13:50.648262Z 15593 Query update jd set updated_time='2023-10-30 20:13:50.647629', view=7 where id=1 2023-10-30T11:13:50.648899Z 15593 Query commit 2023-10-30T11:13:50.649800Z 15593 Query SET autocommit=1 2023-10-30T11:13:50.651617Z 15585 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=6 2023-10-30T11:13:50.653095Z 15585 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=6 and jdview0_.jd_id=1 2023-10-30T11:13:50.654579Z 15585 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.65412', 1, 6) 2023-10-30T11:13:50.656371Z 15585 Query update jd set updated_time='2023-10-30 20:13:50.65523', view=8 where id=1 2023-10-30T11:13:50.657266Z 15585 Query commit 2023-10-30T11:13:50.657976Z 15585 Query SET autocommit=1 2023-10-30T11:13:50.660051Z 15587 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=8 2023-10-30T11:13:50.661734Z 15587 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=8 and jdview0_.jd_id=1 2023-10-30T11:13:50.663630Z 15587 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.663013', 1, 8) 2023-10-30T11:13:50.664883Z 15587 Query update jd set updated_time='2023-10-30 20:13:50.664416', view=9 where id=1 2023-10-30T11:13:50.665570Z 15587 Query commit 2023-10-30T11:13:50.666166Z 15587 Query SET autocommit=1 2023-10-30T11:13:50.668108Z 15590 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=5 2023-10-30T11:13:50.669552Z 15590 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=5 and jdview0_.jd_id=1 2023-10-30T11:13:50.671998Z 15590 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.67145', 1, 5) 2023-10-30T11:13:50.674852Z 15590 Query update jd set updated_time='2023-10-30 20:13:50.672787', view=10 where id=1 2023-10-30T11:13:50.678169Z 15590 Query commit 2023-10-30T11:13:50.678898Z 15590 Query SET autocommit=1 2023-10-30T11:13:50.680488Z 15588 Query select user0_.id as id1_40_0_, user0_.created_time as created_2_40_0_, user0_.updated_time as updated_3_40_0_, user0_.apple_id as apple_id4_40_0_, user0_.badge as badge5_40_0_, user0_.email as email6_40_0_, user0_.fcm_token as fcm_toke7_40_0_, user0_.image as image8_40_0_, user0_.kakao_id as kakao_id9_40_0_, user0_.nickname as nicknam10_40_0_, user0_.password as passwor11_40_0_, user0_.role as role12_40_0_, user0_.agreement as agreeme13_40_0_, user0_.profile as profile14_40_0_ from user user0_ where user0_.id=1 2023-10-30T11:13:50.688167Z 15588 Query select jdview0_.id as id1_19_, jdview0_.created_time as created_2_19_, jdview0_.jd_id as jd_id3_19_, jdview0_.user_id as user_id4_19_ from jd_view jdview0_ where jdview0_.user_id=1 and jdview0_.jd_id=1 2023-10-30T11:13:50.690280Z 15588 Query insert into jd_view (created_time, jd_id, user_id) values ('2023-10-30 20:13:50.689792', 1, 1) 2023-10-30T11:13:50.691383Z 15588 Query update jd set updated_time='2023-10-30 20:13:50.690916', view=11 where id=1 2023-10-30T11:13:50.692073Z 15588 Query commit 2023-10-30T11:13:50.692789Z 15588 Query SET autocommit=1
Plain Text
복사
General Log를 확인해보니 SELECT ~ for update를 통해 조회하는걸 확인할 수 있고 INSERT UPDATE COMMIT이 트랜잭션 별로 순차적으로 진행되는걸 확인할 수 있습니다.
또한 Server Log에 Exception도 발생하지 않았고 DB에 데이터도 정상적으로 변경되었습니다!

 마치며

당장 DeadLock이 발생한건 해결하였지만 한 가지 의문이 남았습니다.
DB에서 트랜잭션이 Lock을 획득할 때까지 기다려주는 innodb_lock_wait_timeout 은 50초이고 HikariCP의 커넥션 획득 timeout은 30초인데 만약 어떠한 이유로 늦어져서 timeout으로 인한 Lock 획득에 실패하게 되면 어떻게 해야할까?
이러한 의문은 아래의 방식으로 해결할 수 있을거란 생각을 했습니다.
1.
Batch 방식의 UPDATE
기존엔 조회수 증가 API를 호출하면 바로 UPDATE를 하는 방식이었기에 DeadLock에 쉽게 노출되었습니다.
실시간성을 살짝 포기하여 조회수 증가 API를 호출하면 서버 메모리 혹은 Redis에 조회수를 누적해두고 Scheduler를 이용해 n분마다 누적된 조회수를 UPDATE하는 방식으로 변경하면 DeadLock에서도 벗어날 수 있고 가장 느린 UPDATE SQL을 사용하는 빈도도 줄일 수 있는 좋은 방식일거 같았습니다.
2.
Spring-Retry
DB뿐만 아니라 Spring에도 @Transactional을 통한 트랜잭션이 존재합니다.
Spring의 AOP 기능을 이용하며 트랜잭션 내에서 Exception이 발생하면 Rollback을 하도록 되어있습니다.
Spring-Retry는 Spring 트랜잭션 내에서 지정된 Exception이 발생하면 해당 메서드를 다시 호출하는 방식으로 재시도를 할 수 있게 해주는 라이브러리입니다.
이걸 이용함으로써 LockAcquisitionException 과 같은 Exception을 핸들링 할 수 있는 방식도 존재하였습니다.

 참고 문헌

[DB] 락(Lock) - MySQL 8.0 InnoDB
🧐 서론 데이터베이스에는 트랜잭션이 존재합니다. 트랜잭션을 통해 하나의 작업 단위를 묶어서 ACID 원칙을 지키기 위해 노력합니다. 하지만, ACID 원칙이 언제나 완벽하게 지켜지진 않습니다. 너무 완벽하게 지키기 위해 어떤 상황에서라도 지키려고 한다면, 동시성이 떨어지는 문제가 발생하기 때문이죠! 그렇기 때문에 ACID 원칙을 적절하게, 상황에 맞게 유지시키면서 동시성을 높일 수 있게 DB에서 기능을 제공합니다. 바로 Isolation level을 통해서요! (트랜잭션에 대한 추가 설명은 이전 글을 참고해주세요!) 결국, Isolation level 별 적절한 Lock을 진행하고, 이는 DBMS마다 다릅니다. 저는 MySQL InnoDB 기준으로 어떤 Lock이 있는지 알아보도록 하겠습니다. 🫢 본론 ..
https://kdhyo98.tistory.com/101
[JPA] 낙관적 락(Optimistic Lock)과 비관적 락(Pessimistic Lock)에 대해
낙관적 락, 비관적 락에 대해 JPA를 사용하여 데이터베이스와 연결된 애플리케이션을 개발할 때, 동시성 처리와 관련된 이슈가 발생할 수 있다. 이러한 이슈를 해결하기 위한 방법 중 하나는 락(lock)을 사용하는 것이다. 이번 포스팅에는 낙관적 락과 비관적 락에 대해 알아보고, 예제코드와 이를 사용하는 이유 및 장단점을 함께 써보겠다. 낙관적 락(Optimistic Lock) 낙관적 락은 충돌이 거의 발생하지 않을 것이라고 가정하고, 충돌이 발생한 경우에 대비하는 방식이다. 낙관적 락은 JPA에서 버전(Version) 속성을 이용하여 구현할 수 있다. 낙관적 락의 특징으로는 충돌 발생확률이 낮고, 지속적인 락으로 인한 성능저하를 막을 수 있다. 아래는 예시 코드이다. 1. Entity @Entity pu..
https://mozzi-devlog.tistory.com/37
낙관적 락과 비관적 락은 갱신 손실 문제를 어떻게 해결하는가
동작 원리와 선택 기준에 대하여
https://velog.io/@balparang/낙관적-락과-비관적-락은-Race-Condition을-어떻게-해결하는가
Spring - Retry
모든 코드는 Github에 있기 때문에 함께 보시면 더 이해하기 쉬우실 것 같습니다.(공부한 내용을 정리하는 Github와 이 모든 내용을 담고 있는 블로그가 있습니다. )Spring의 재시도 기능은 스프링 배치에 포함되어 있다가 2.2.0 버전부터 제외되어 현재
https://velog.io/@backtony/Spring-Retry