문제 발견
와탭은 자체 서비스를 모니터링하는 데에도 물론 와탭 제품을 사용합니다. 와탭에서 제공하는 다양한 모니터링 도구들 중에서 아래 트랜잭션 히트맵은 실시간으로 애플리케이션 트랜잭션 상태를 추적할 수 있습니다. 간단히 빨간색이면 문제가 있는 것이고 파란색은 문제가 없다는 것을 뜻해요. 어느날 이 히트맵 트랜잭션을 통해 특정 시간대에 응답 시간이 비정상적으로 길어진 것을 감지했고, OOM으로 인해 서버가 재기동된 것까지 확인이 되었었습니다.
위 이미지는 와탭 공식 문서에 있는 예시 화면이고요. 저런 점들이 찍힌 부분들을 드래그하면 드래그 안에 속한 여러 트랜잭션들의 상세한 정보도 볼 수 있습니다. 이번 이슈에서는 OOM 발생 직전에 처리속도가 느리고 빨간 트랜잭션들이 다량으로 나타났었어요.
가령, 위 이미지처럼 세로로 빨간 점들이 많이 보였다는 것이죠. 평소와 달리 이슈가 생기기 직전에 생긴 모양이기 때문에 직접적인 영향이 있을 확률이 굉장히 높아보입니다. 드래그하여 회색 박스 형태로 세로 부분을 조회를 해보면 상세한 정보들이 나오는데요. 당시 원인은 제공하는 여러 모니터링 제품들 중에서 고객이 DB 모니터링 제품에서 여러 쿼리 정보 데이터들을 조회하다가 해당 페이지에서 OOM 이 발생했던 것이었습니다.
JVM은 비정상적으로 종료되면 hs_err (HotSpot JVM), javacore (IBM) 로그 파일을 남기도록 되어있습니다. OOM이 발생하면 가장 먼저 확인해봐야할 로그라고 보면 되겠죠? 그래서 먼저 인지한 것은 로그 파일을 통해 처리가 느렸던 슬로우 쿼리 정보들을 조회하는 API에서 문제가 발생했다는 사실이었어요.
앞으로 말씀 드리는 쿼리를 조회한다는 뜻은 와탭 모니터링 서비스에 수집된 쿼리 정보의 지표(metric) 데이터를 조회한다는 뜻입니다.
문제 분석
쿼리 정보를 조회하는데 OOM 이 발생했다는 것은 OOM 이 발생할만큼 메모리에 어마무시한 양을 올렸다면 당연히 의심할 수 있는 것은 쿼리의 길이밖에 없다고 생각했습니다. 다시 말해서, 고객 DB에서 굉장히 긴 쿼리가 발생했고, 그 쿼리가 와탭 데이터 수집 서버에 저장되어 조회되었다는 뜻이죠. 하지만 정확한 원인 추적이 필요합니다.
느린 쿼리를 조회하는 API 코드상에서도 당연히 데이터를 조회하는 부분밖에는 의심할 곳이 없어보였습니다. 로그 외에 추가적으로 제가 알 수 있었던 건 트랜잭션 상세 정보를 통해 OOM 발생 당시 무엇을 조회하려고 했는지 알 수 있었습니다. 조사를 해보니 비교적 꽤 큰 데이터 파일을 읽었었고, 그 용량이 대략 150mb 정도되었다는 것을 발견했습니다.
정확한 원인 검증을 위해서 총 150mb 정도되는 쿼리 파일을 만들어서 테스트하기로 했습니다. 와탭에서는 자체 File DB 시스템을 만들어 사용하고 있기 때문에 이 쿼리 파일이 RDB의 150mb정도 되는 긴 쿼리 텍스트 데이터들이 담긴 테이블과 비슷하다고 생각해주시면 좋을거 같습니다.
먼저, 로컬 환경에서도 애플리케이션을 실행하면 heap 메모리를 모니터링 할 수 있도록 환경을 만들었습니다. 그리고 이 상태에서 아까 만들었던 약 150mb 쿼리 파일들을 조회해보았습니다.
역시 예상대로 메모리가 급격히 치솟는것을 확인할 수가 있었는데요. 기본적으로 애플리케이션이 돌아가는 데에 필요한 메모리들과 파일에 있는 바이트 코드들을 객체로 변환한다는 것까지 고려하면 얼추 150mb 파일 읽으면 저렇게 많이 치솟을 수 있지 않을까? 하고 처음엔 조금 짜맞추는 식으로 생각을 하려고 했던것 같습니다.
해결 시도
와탭에서 File DB를 읽을 때도 당연히 RDB처럼 select 할 때 조건(where)들에 일치하는 데이터를 가져와 객체로 사용하게 됩니다. 그래서 이런 시도를 해보았습니다. 데이터를 하나씩 가져올 때, 쿼리 텍스트가 특정 길이 이상이 되면 substring 해버리고, substring 된 문자열을 DB에서 가져온 긴 SQL 텍스트 대신 사용하기로요.
그랬더니 정말 놀랍게도 약간의 메모리만 올랐습니다.
그런데 이는 다시 생각해보니 단순히 substring 한다고해서 힙 메모리에 할당되는 양이 줄어들 수는 없었습니다. 오히려 이전보다 더 늘어나야 정상이지 않았을까요? 왜냐하면 이미 메모리에는 객체들이 할당되어 있는 상태이고 이걸 substring 하면 즉, String 클래스의 substring 메소드 내부에서 `new String()`을 하기 때문에 String constant pool 이 존재하는 힙 메모리가 더 늘어나는 효과가 있기 때문입니다.
그렇다면 substring된 문자열을 사용하면서 기존의 select된 객체들의 참조가 제거되어 바로 GC가 되었던 것일지도 모르겠다고 잠깐 생각을 해봤는데요. 하지만 단순히 참조 제거 대상이 갑자기 많아진다고 GC를 하는 것은 절대 아닙니다. 참조 제거 대상을 결정하고 제거 되어지는 때는, 즉 Mark & Sweep 은 GC 자체가 수행될 때이기 때문에 먼저 일정 수준 Eden 영역에 메모리가 차야합니다.
게다가 GC 대상이 많아져서 GC가 되어 차트가 낮게 나타난다고 생각했다면 콘솔에 굉장히 많은 GC 로그들을 볼 수 있었을 겁니다. JVM option 중에 -verbose:gc 를 사용하면 GC 하는 것을 직접 콘솔에서 확인해볼 수가 있는데요. 쿼리들을 읽을 때, 확인해보니 2~3번정도의 GC만 일어났었어요.
쿼리를 조회한다는 뜻은 와탭 모니터링 서비스에 수집된 쿼리 정보의 지표(metric) 데이터를 조회한다는 뜻입니다.
그렇다면 substring 했을 때는 메모리가 낮고, 원본 쿼리 텍스트를 사용했을 땐 다시 메모리가 치솟는 현상은 어떻게 설명할 수 있을까요? 원본 쿼리 텍스트를 사용할 때도 substring 했을때와 마찬가지로 -verbose:gc 옵션을 넣어 실행해보면, 오히려 어마무시한 GC 로그들을 대량 확인할 수 있었습니다. 즉, 많은 GC가 발생하여 차트가 낮게 나온 것은 아니라는 것이죠.
따라서 쿼리를 조회하는 곳의 코드가 문제가 아니라고 생각했습니다. 이 결론을 좀 더 명확하게 하기 위해서 파일 조회 이후에 힙덤프를 생성해보도록 했습니다.
근본 원인 파악
substring()을 적용한것과 적용하지 않을 것을 비교를 했고, 역시 쿼리를 조회하는 곳의 코드가 문제가 아니라는 결론의 근거를 볼 수있었습니다.
1. substring()을 적용하든 안하든 전체 힙 메모리가 비슷하다. OOM도 발생할 수 없다.
2. 추측한대로 String 객체가 오히려 substring했을 때 더 늘어난 것을 확인할 수 있다.
이제 데이터를 불러오는 쪽이 아니라 좀 더 아래 로직을 살펴보았습니다. 로깅을 여러곳에 하고, GC 로그가 어느 구간에서 가장 많이 발생하는지 보았습니다. 단번에 찾을 수 있었습니다. 원인은 데이터를 응답할 때 사용하던 ByteArrayOutputStream이 문제였습니다.
이게 원인이 되었던 이유는 무엇이었을까요?
ByteArrayOutputStream
와탭에서는 Spring을 사용하지만 일부 API들은 일반적인 객체 반환 방식 대신에 HttpServletResponse의 OutputStream을 활용하여 데이터를 직접 스트림으로 flush하는 방식을 사용하고 있습니다. 이 방식이 좀 생소한 분들을 위해 간략하게 샘플 코드로 같이 보시면 아래와 같은 모습입니다.
@RestController
public class StreamDataController {
@GetMapping("/stream")
public void streamData(HttpServletResponse response) {
String data = "Sample";
response.setContentType("text/plain");
response.setCharacterEncoding("UTF-8");
try (OutputStream out = response.getOutputStream()) {
out.write(data.getBytes("UTF-8"));
out.flush(); // 데이터를 클라이언트에게 전송
} catch (IOException e) {
}
out.close();
}
}
여기에 더불어 실제로는 데이터를 `response.getOutputStream()`에 바로 wrtie하지 않고 flush할 데이터들을 ByteArrayOutputStream의 버퍼에 쌓아둔 다음에 한번에 write하도록 되어있습니다. 어쨌든 이 ByteArrayOutputStream가 문제가 되었었는데요.
`ByteArrayOutputStream` 클래스의 구현을 살펴보면 `write(byte[] b, int off, int len)` 메소드는 버퍼가 데이터를 저장할 수 없을 만큼 작으면 새로운 배열을 만들어 기존의 데이터를 복사하는 것을 확인할 수가 있어요. 아래는 Java 17 구현입니다.
위 코드에서 보듯이 `copyOf()`는 기존의 데이터를 새로운 배열에 복사합니다. 이 복사하는 로직이 OOM을 유발시켰던 것이었죠.
결론
실제로 OOM이 발생했을 당시에 생성되었던 힙덤프도 분석해보면 byte 배열이 굉장히 많았었습니다. 더 들어가서 이 byte 배열의 요소들에 들어가 있는 숫자들을 스트림에 write할 때 사용하는 charset으로 디코딩하면 응답하려고 했던 값들을 아래처럼 직접 확인할 수도 있습니다.
너무 많은 데이터가 flush되지 않도록 미리 max size를 정해두고 있긴 하지만 안그래도 그 긴 쿼리 텍스트들을 다량으로 복사하다보면 문제가 발생할 수 밖에 없을 것입니다.
그나저나 그 긴 쿼리들의 정체는 무엇이길래 몇 메가바이트나되는 크기의 파일을 가졌을까요? 문제가 되었던 긴 쿼리는 `SELECT a,b,c FROM table WHERE a IN 1,2,3,4,5,6,7,....`과 같이 `in`절에서 끝도 보이지 않는 쿼리가 문제였습니다. 뭔가 고객사에서 쿼리를 동적으로 생성하는 과정에서 프로그래밍적인 오류가 있지 않을까 싶은데요.
어쨋든 장기적인 해결책으로는 더 근본적인 접근이 필요할 것 같습니다만, 당장엔 이런 쿼리를 전체 텍스트를 보여주는 것이 고객에게 의미가 있다곤 생각하지 않아 문자열을 특정 길이로 자르는 방식으로 대응하여 해결했습니다.
이렇게 OOM 문제를 해보았는데요. OOM 문제를 해결하기 위해서 중요하다고 생각하는 것은 OOM 발생시 hs_err 로그 파일이 잘 생성이 되는지 그리고 힙덤프 파일이 잘 생성이되는지 미리 확인이 필요할 것 같습니다. 또 힙덤프를 어떤 툴로 어떻게 분석할 수 있는지 미리 알아두면 큰 도움이 되겠다고 생각했습니다.
참고 자료 링크
'기술과 경험' 카테고리의 다른 글
| 릴리즈 노트 작성 반복 작업 자동화 (0) | 2024.05.05 |
|---|---|
| 현실적인 신입 개발자의 회사 깃 도입기 (1) | 2023.06.15 |
