프로젝트를 수행하면서 조회 성능 관련 이슈가 발생했고 이를 해결하고 개선하는 과정을 순차적으로 작성해두려고 한다.
제너럴한 케이스도 포함되어 있고 프로젝트 환경에 묶인 특수한 케이스도 있어서 다른 누군가에게 도움이 될 지는 모르겠지만 일단 까먹기 전에 정리해두려고 한다.
조회가 느려요
프로젝트 수행 중 공통 코드 조회가 느리다는 문의가 들어왔다.
특정 화면에서 공통코드 조회가 느려지면서 성능이 안나온다는 내용이었다.
데이터가 많아서 오래 걸리는 경우에도 0.n 초 정도로 응답을 받았었고 대부분의 경우에는 0.02 ~ 0.03 초가 걸리는 공통코드 조회 API인데 특정 케이스에서 2~3초정도 병목이 걸리는 현상이 발생한다고 하여 확인해 보았다.
확실히 뭔가 이상하다.
다른 요청에 비해 응답 size가 크다고 하더라도 비슷한 사이즈인 64.8 kB를 응답받은 시간이 124ms인 것에 비해 과하게 느리다.
어디서부터 확인해봐야 할 지 고민을 좀 해보았다.
구조 요약
문제가 발생한 환경 구조는 자세하게 작성할 수는 없지만 대략적인 구조를 요약하면 이렇다.
1. 공통 코드는 DB에 저장되어 있다.
2. 특정 시간마다 배치 작업으로 Redis 캐시에 올려둔다.
3. 조회시 파라미터로 전달된 공통 코드 카테고리를 키로 Redis 캐시를 먼저 조회하고, 캐시 히트 시에는 리턴, 미스 시에는DB를 조회하여 리턴한다.
병목 지점 찾기
문제를 확인하고 나서 어느 지점에서 병목이 발생하는건지 병목 가능성이 있는 부분마다 로그를 찍어 하나하나 확인해보았다.
1. Redis 캐시에서 데이터를 JVM 힙 메모리로 로드
아래 샘플 코드와 같이 redisTemplate.opsForHash()로 multiGet 해오는 로직 앞뒤로 시스템 타임을 찍어 디버깅 로그를 추가해서 확인해보았지만 병목이 걸리는 요청에서도 12 ms 로 매우 빠르게 처리가 되었다.
@Slf4j
@Component
public class CommonCodeManager {
public List<CommonCode> findCommonCodes(List<String> categories) {
List<CommonCode> result = new ArrayList<>();
long redisGetStartTimeMillis = System.currentTimeMillis();
List<Object> values = redisTemplate.opsForHash().multiGet(COMMON_CODE_KEY, (List) categories);
log.debug("redis load time {} ms", (System.currentTimeMillis() - redisGetStartTimeMillis));
/**
* 매핑 로직
*/
return result;
}
}
2. 메모리에 로드된 코드 리스트 매핑
여기에 작성할 수는 없지만 메모리에 로드된 코드 리스트를 필요한 양식에 맞게 stream을 열어 매핑하는 로직이 있는데 이 로직 앞뒤로도 시스템 타임을 찍어 로그를 남겨줬다.
하지만 역시 메모리에서 순회하는 작업이다 보니 로그상엔 0ms가 찍혀있었다.
3. nginx 네트워크 타임
백엔드 서비스가 nginx 리버스 프록시로 구성이 되어있는데 nginx에서 병목이 걸리는 것은 아닐까?
nginx.conf 파일에 로그 포맷을 설정할 때 request_time과 upstream_response_time을 함께 기록해 차이를 확인해보기로 했다
# ...
http {
# ...
log_format web_log ... 'rt="$request_time" urt="$upstream_response_time"'
# ...
}
nginx 로그 옵션인 $request_time과 $upstream_response_time은 각각 다음과 같다고 한다.
$request_time
클라이언트 요청 수신부터 클라이언트 응답 전송 완료까지 전체 시간
$upstream_response_time
nginx 와 upstream 서버 간 통신 및 서버 처리 시간
하지만 결과는
rt="2.361"
urt="2.361"
결국 백엔드 애플리케이션쪽에서 병목이 걸리는 것이 확실해졌다. 다시 API 로그를 살펴보자.
4. 응답 바디 직렬화
이어서 API 요청의 로그를 살펴보다 보니 병목 시간만큼 뜨는 부분이 보였다.
...
YYYY-MM-DD 13:42:34.775 DEBUG NNNNN --- [http-nio-XXXX-exec-6] ...CommonCodeManager : redis load time 12 ms
YYYY-MM-DD 13:42:34.775 DEBUG NNNNN --- [http-nio-XXXX-exec-6] ...CommonCodeManager : common code mapping time 0 ms
YYYY-MM-DD 13:42:37.136 DEBUG NNNNN --- [http-nio-XXXX-exec-6] m.m.a.RequestResponseBodyMethodProcessor : Using 'application/json', given [application/json] and supported [application/json, application/*+json, application/json, application/*+json]
...
이 부분에서 응답 바디를 직렬화하는 과정에서 병목이 생기는건 아닐까? 하는 생각이 들었다.
프로젝트의 공통 응답 포맷이 레거시 시스템과의 호환을 위해 JSON depth가 깊어 복잡한데, 그렇기에 직렬화 과정에서 병목이 생길 수 있지 않을까 하는 의심부터 시작했다.
그렇지만 지금 글을 쓰고 있는 시점에서 생각해보니 응답 데이터 크기가 비슷한 API 요청에서조차 병목 발생시에 응답 시간이 크게 차이가 났는데 이걸 못알아보고 있었다. (매우 멍청쓰)
어찌되었든 기록은 남겨야하니까 응답 직렬화 시간을 체크하기위해 아래처럼 MappingJackson2HttpMessageConverter의 writeInternal 메소드를 오버라이드해서 기존 컨버터 앞에 등록해준 후 테스트를 해보았다.
@Configuration
public class WebConfig implements WebMvcConfigurer {
public MappingJackson2HttpMessageConverter loggingJacksonConverter(ObjectMapper objectMapper) {
return new MappingJackson2HttpMessageConverter(objectMapper) {
@Override
protected void writeInternal(Object object, HttpOutputMessage outputMessage)
throws IOException {
long serializeStartTimeMs = System.currentTimeMillis();
super.writeInternal(object, outputMessage);
log.info("serialize time : {} ms", (System.currentTimeMillis() - serializeStartTimeMs));
}
};
}
@Override
public void extendMessageConverters(List<HttpMessageConverter<?>> converters) {
ObjectMapper mapper = new ObjectMapper();
/**
* objectMapper 커스텀 설정
*/
converters.add(0, loggingJacksonConverter(mapper));
}
}
역시나 수 ms 이내에 성공해버렸다.
5. Full GC
로그만 확인했을 때에는 중간에 2초가 넘게 스레드가 멈추는 것 처럼 보이는데 여기까지 와서야 GC 로그 볼 생각을 했다.
JVM 옵션으로 아래 옵션을 주어서 이미 GC 로그를 기록하고 있었기 때문에 별도 추가 설정 없이 로그 파일을 확인해보았다.
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:$LOG_PATH/gc_log.log
# 그 외 Garbage Collector 설정 및 로그 파일 관련 설정
찾았다.
YYYY-MM-DDT13:42:34.800+0900: 5700.195: [Full GC (Ergonomics) [PSYoungGen: 807936K->489359K(930816K)] [ParOldGen: 2097128K->2097128K(2097152K)] 2905064K->2586487K(3027968K), [Metaspace: 307277K->307277K(1343488K)], 2.360787 secs] [Times: user=4.34 sys=0.00, real=2.36 secs]
조회시에 Full GC가 발생해서 Stop the world로 인해 병목이 걸리는 것이었다.
이걸 이제 어떻게 해결할지 고민을 해야했다.
딱 떠오르는 방법으로는 메모리가 튀게 만드는 소스를 수정하거나 GC 튜닝을 해 GC로 발생하는 오버헤드를 줄이는 방법이 있어 보였다.
처음엔 개발이 잘못되었으니 아예 소스 구조를 변경하는 것을 우선적으로 고려했으나, 프로젝트 개발 기간이 이미 종료되었고 소스 수정이 어려운 문제가 있어 GC 튜닝으로 문제를 해결해보기로 했다.
포스팅이 길어져 다음 포스팅에 이어서 GC 튜닝 및 테스트 결과를 기록하겠다.