https://gani-dev.tistory.com/141
지난 글에 이어서, 모든 유저 포인트 조회 기능을 개선해보려고 한다.
이전 상황
- 유저 포인트 조회 기능 성능 향상을 위해 SQL을 개선했다
- 서브쿼리를 이용하여 조인 비용을 줄임
- 성능테스트 - MTT 는 18초 -> 9초 46.73% 속도 개선됨
- 그러나 아직도 9초나 걸린다는 문제가 있음
- 실행 시간 측정 결과 , DB보다 Java 코드에서 처리하는데 시간이 더 오래걸림
문제점 파악
성능테스트 결과, 모든 유저의 포인트를 조회하는 기능은 평균 9초가 걸린다.
코드 내부에서 메서드별 실행 시간을 측정해본 결과 , DB 조회 시간보다, Java 코드 단에서 실행된 시간이 3배이상 더 걸린다는 문제점을 파악했다.
- 비즈니스 로직을 처리하는데 총 걸린 시간 : 7869ms
- DB 조회하는데 걸린 시간 : 1894ms
어디서 시간을 잡아먹는지 병목 지점을 찾아보자 !
요청 처리 로직
- Controller에서 요청을 받음 , pointService.getAllUserPoint() 메서드 호출
- PointService에서 getAllUserPoint() 실행 , pointSearchService.findAllUserPoint() 호출
- PointSearchService에서 pointHistoryRepository.findAllUserPoint() 호출하여 DB 조회 및 결과 리턴
//controller
@ApiVersion("1")
@GetMapping("/allUserPoint")
public ResponseEntity<SuccessSingleResponse<List<UserPointResponse>>> getAllUserPoint() {
List<UserPointResponse> responses = pointService.getAllUserPoint();
return ResponseEntity.ok()
.body(new SuccessSingleResponse<>(HttpStatus.OK.getReasonPhrase(), responses));
}
//PointService
public List<UserPointResponse> getAllUserPoint() {
return pointSearchService.findAllUserPoint();
}
//PointSearchService
public List<UserPointResponse> findAllUserPoint() {
List<UserPointResponse> allUserPoint = pointHistoryRepository.findAllUserPoint(); //DB 조회
return allUserPoint;
}
병목지점 분석
코드 내에서 병목 지점 찾기
코드 내에서 실행 시간을 다시 측정해보자
//Contoller
@ApiVersion("1")
@GetMapping("/allUserPoint")
public ResponseEntity<SuccessSingleResponse<List<UserPointResponse>>> getAllUserPoint() {
// 시작 시간 측정
long startTime = System.currentTimeMillis();
log.info("checkTime test - start : " + startTime); // 1722531056245 ms
// 비즈니스 로직 실행
List<UserPointResponse> responses = pointService.getAllUserPoint();
// 종료 시간 측정
long endTime = System.currentTimeMillis();
long duration = (endTime - startTime);
log.info("checkTime test - end : " + endTime); // 1722531062864 ms
log.info("checkTime test - duration : " + duration); // 6619 ms
return ResponseEntity.ok()
.body(new SuccessSingleResponse<>(HttpStatus.OK.getReasonPhrase(), responses));
}
//PointService
public List<UserPointResponse> getAllUserPoint() {
// 시작 시간 측정
long startTime = System.currentTimeMillis();
log.info("checkTime PointService - start : " + startTime); // 1722531061412 ms
return pointSearchService.findAllUserPoint();
}
//PointSearchService
public List<UserPointResponse> findAllUserPoint() {
// DB 조회 시작 시간 측정
long startTime = System.currentTimeMillis();
log.info("checkTime findAllUserPoint db join - start : " + startTime); // 1722531061640 ms
//DB 조회
List<UserPointResponse> allUserPoint = pointHistoryRepository.findAllUserPoint();
//DB 조회 종료 시간 측정
long endTime = System.currentTimeMillis();
log.info("checkTime findAllUserPoint db join - endTime : " + endTime); // 1722531062860 ms
long duration = (endTime - startTime);
log.info("checkTime findAllUserPoint db join - duration : " + duration); // 1220 ms
return allUserPoint;
}
측정 결과
- Controller에서 pointService.getAllUSerPoint() 메서드 호출 시간 : 1722531056245 ms
- PointService의 getAllUserPoint() 메서드 시작 시간 : 1722531061412 ms
- PointSearchService의 findAllUserPoint 메서드 내 DB 조회 시작 시간 : 1722531061640 ms
- PointSearchService의 DB 조회 종료 시간 : 1722531062860 ms
- Controller에서 pointService.getAllUSerPoint() 메서드 호출 종료 시간 : 1722531062864 ms
측정 결과 스크린샷
-- [io-8080-exec-96] c.c.d.d.p.service.PointSearchService : checkTime findAllUserPoint db join - endTime : 1722531062860
분석
- Controller에서 pointService.getAllUSerPoint() -> PointService의 getAllUserPoint() 시작 까지 걸린 시간 : 5167ms
- pointService.getAllUserPoint() -> PointSearchService의 DB 조회 시작 까지 거린 시간 : 232ms
- PointSearchService의 DB 조회에 걸린 시간 : 1220ms
- 총 요청에 걸린 시간 : 6619ms
이번 경우에는 요청을 처리하는데 6.6초 가 걸렸다.
그 중에 Controller에서 pointService.getAllUserPoint() 호출해서 , getAllUserPoint() 메서드 시작까지 5초가 걸렸고,
DB 조회에 1.2초 걸렸다.
DB 조회 시간보다 Controller에서 PointService의 getAllUserPoint를 실행가기까지 5배 넘는 시간이 걸렸다.
병목 지점 스레드 확인하기
아까 병목 지점에서 왜 5초나 걸렸는지 확인하기 위해, 스레드를 확인해 봤다. (http-nio-8080-exec-96 스레드 )
http-nio-8080-exec-96 스레드를 위 사진에서 확인해 보면, 아래와 같다.
- 1:50:54부터 1:50:55까지 - Run 상태
- 1:50:55부터 1:51:01까지 - Park 상태 (5초 대기)
- 1:51:01부터 1:51:02까지 - Run 상태
http-nio-8080-exec-96 스레드 외에도 상당히 많은 스레드가 규칙적으로 동시에 Park 상태를 이룬 것을 확인할 수 있었다.
스케줄링을 생각한다면, 스레드가 park 상태일 때, 당연히 다른 스레드가 Run 상태가 되어야한다고 생각했었는데, 오히려 같이 Park 상태가 되어 혼란스러웠다.
동시에 많은 스레드가 Park 된 이유는 무엇일까 ?
성능 테스트를 진행하면서 , CPU 사용량을 측정해봤더니 거의 100%를 찍었다. ㅋㅋ....
성능 테스트와, 프로그램 실행을 모두 한 로컬 컴퓨터로 진행하다보니 시스템 과부하가 발생한 것 같다...
( 그중에 Mysql과 Java가 CPU 사용량 1등...)
CPU 사용량이 100%에 도달하면서 스레드가 충분한 CPU 시간을 할당받지 못하고, 이로 인해 주기적으로 park 및 run 상태를 반복한다. 그 외에도 가비지 컬렉터 작업 수행 등의 이유가 있을 수 있다.
개선 방법
현재 '모든 유저 포인트 조회 API' 의 MTT는 9초다.
물론 테스트 서버의 환경만 개선된다면 9초보다 훨씬 빠른 결과를 만들어낼 수도 있다.
하지만, 서버 환경 성능에 의존해서만은 안되며 계속해서 효율적이고 최적의 코드를 만들어내려고 노력해야한다.
'모든 유저 포인트 조회 API'를 지금보다 더 빠르게 개선할 수 있는 방법이 존재하긴 한다.
현재 API의 로직은 모든 유저의 포인트를 전부 조회하기 때문에 비효율적이다.
N만명의 유저가 존재한다면, N만명의 유저 포인트를 전부 계산해서 들고오기 때문이다.
한번 조회했을 때, N만명의 정보가 모두 필요하진 않기때문에, 페이지네이션을 이용하여 한번 조회할때마다 M명씩(일정한 수만큼) 조회하는 게 좋다.
위 방법을 알고는 있었지만, 조금 더 최적화된 상태에서 페이지네이션을 이용하고 싶었기에 끝까지 속도 개선에 신경 썼던 것 같다. ㅜ
휴...
현재 해결해야하는 문제가 몇가지 더 남았기 때문에, '모든 유저 포인트 조회' API 개선기는 여기서 잠시 스탑해야할 것 같다 ~
읽어주시고, 도움 주신분들 너무 감사합니다 ~! 그럼 안뇽 !
ps. 저의 궁금증을 같이 고민해주고, 도와주신 기가바이트갱 영철,신지님께 이 글을 바칩니다. 감사합니다 ~!
결론
- 유저 포인트 조회 기능 성능 향상을 위해 SQL을 개선했다
- 서브쿼리를 이용하여 조인 비용을 줄임
- 성능테스트 - MTT 는 18초 -> 9초 46.73% 속도 개선됨
- 그러나 아직도 9초나 걸린다는 문제가 있음
- 실행 시간 측정 결과 , DB보다 Java 코드에서 처리하는데 시간이 더 오래걸림
- Java 병목 원인 : CPU 사용량 100%
- 페이지네이션을 이용한다면 더 효율적인 API가 될 것!
'개발일지 > 문제 해결하기 ~' 카테고리의 다른 글
서브쿼리를 이용한 조인 쿼리 개선하기(2) -쿼리 개선기 (0) | 2024.08.01 |
---|---|
서브쿼리를 이용한 조인 쿼리 개선하기(1) - 현재 상황 분석 (0) | 2024.07.30 |
연속 요청으로 인한 데드락 문제 해결하기 (1) | 2024.07.24 |
꾸준히 기록할 수 있는 사람이 되자 !