[쿠링] Pattern 하나로 서버 OOM발생시켜 다운시키기 (Heap Dump 보기)
1. 처음엔 문제인 줄 몰랐다...
현 쿠링은 엄청 비싼 인스턴스를 사용하지는 않고 있기 때문에 인스턴스 한대당 Memory가 512MB에 불과한 서버를 사용 중이다. (대신 값싼 거 3대로 운영 중)
심지어 메인서버는 Heroku이고, 테스트서버와 모니터링 서버는 AWS에서 기동중이다.
(메인 서버 이전이 쉽지가 않다...) 다행히 지금은 메인서버를 AWS로 이전했고, test서버를 Heroku로 사용중이다!
평상시에는 크게 문제처럼 느껴지지 않던 부분이 시간적 여유를 갖고 보니 조금은 어색하게 느껴진 부분이 있었다.
우선 다음 모니터링 기록을 살펴보자
▶ Heap : G1 Eden Space
▶ Heap : G1 Survivor Space
G1 Eden 영역에 수시로 생성되고 있는 양이 어림잡아 170MB, 그중 Survivor로 살아남는 녀석들은 MAX 7MB.
추가로 예전 GC도 일부 참고해봤다~
그럼 163MB나 매번 생성됐다 사라졌다를 반복 중이라는 건데??? 서버 사양이 좋아서 메모리가 넉넉했으면 모를까?
512MB 중 163MB는 32%에 해당되는 양이다.
야 이거 좀 선 넘는데?? 심지어 Old 영역에서 지방령이 되신 분들이 약 100MB 정도 되니.... 412MB 중 163MB이라 생각하면 더 아찔하다....
이때 든 생각은 메모리가 약간 과하게 사용되는 것 같다? 어딘가 누수가 있는 것은 아닐까??
그래도 매인 앱 자체가 다운된 적은 없는 걸로 아는데?? (내 착각이었다...)
2. 집 나간 메모리를 찾아서~
우선 정확한 원인과 확인을 위해 직접 Heroku의 dash-bord로 접근하게 되었다.
R14에 해당되는 경고가 계속 발생하는데??? 이게 뭐지??
Heroku에서는 이를 메모리 초과(메모리 누수)와 관련된 문제가 발생하고 있음을 알려주었다...
대략 지금은 swap영역을 통해 성능은 어느 정도 저하 되더라도 실행은 시키고 있다는 것 같은데....
다음으로는 Memory 관련 로그를 살펴보게 되었다...
야 이거 100% 문제 되는 상황인데? max 608MB를 사용한다고?
그간 사용된 메모리 량을 보니..... 문제가 되는 상황임은 확실하게 인식하게 되었다.
하지만, 메모리 문제가 날만한 이유를 크게 떠올리지 못하였고.... 결국 Heap Dump를 확인해 보는 수밖에 없었다.
2-1) 나는 왜 몰랐을까?
사실은 메인 서버가 다운된 적이 없는 것 이 아니라, 다운 됐지만 Heroku 자동 복구 로직에 의해 금방 재실행되었고, 이를 내가 인지하지 못했다는 점이다....
(사실 테스트 서버 대비 Heroku의 up time이 약 36시간 정도밖에 안된다는 점을 알고는 있었는데... 대수롭지 않게 생각하고 있었다, 테스트 서버는 추가 구현이 반영되는 시점에 다운되는 점 말고는 항상 running 중이었다)
3. 어디가 문제일까?
매인 서버를 재기동하며 상황은 잠시 정상화되었지만, 정확한 원인을 찾아 고쳐야 했습니다.
일단 어떤 동작이 메모리 부족의 트리거가 되었는지 찾아보았습니다. (사용 툴은 MAT)
문제의 힙 덤프파일을 Eclipse MAT을 통해 열어보니,
URLClassLoader가 12% + Java.lang.calss 14% = 약 26% 정도가 차지되고 있었으며,
이때까지만 해도 사실 70% 도 안 넘는 비율인데, 크게 문제 될 부분인가 싶었다?
하지만 내가 추출한 해당 heap dump 파일의 단점이 있다면, 서버 재 실행 후 얼마되지 않는 시점에서 기록한 파일이라는 점?
이 점을 고려하니 충분히 문제가 될 수 있다 판단하였고, 해당 원인 Class가 무엇인지에 대하여 고민하게 되었다.
크게 3가지 hint가 보였다.
- GC 주기가 약 10~ 15분이라는 점 : 이는 공지 scrap 작업 주기와 비슷
- URL이 사용되는 부분은 공지의 URL 뿐이라는 점
- LaunchedURLClassLoader 가 suspect 뜨는 점 봐서는 분명 공지를 Scrap 하고 생산하는 URL 부분과 관련이 있을 것 같다.
또한 주기적으로 축적되는 것으로 미루어 보아 비동기 작업을 할 때 그 수가 늘어난다 판단되었다.
따라서, 해당 원인 지점을 찾기 위해 공지 scrap -> 처리 -> 생성하는 과정을 살펴보았으며 그 원인을 Pattern 객체로부터 찾을 수 있었다.
그렇다 이 문제는 URL의 String, 더 정확히는 Pattern 객체가 지속적으로 생성돼서 발생한 문제였다. 이를 다음 코드에서 더 살펴보자!
4. 문제가 되는 코드
다음 Embeddable로 사용 중인 Value Object가 문제의 근원지점이었다. 어떤 점이 문제였을까??
@Getter
@Embeddable
@NoArgsConstructor(access = AccessLevel.PROTECTED)
public class Url {
private static final String REGEX_PATTERN = "^((http|https)://)?([a-z0-9]+([\\-\\.]{1}[a-z0-9]+)*\\.[a-z]{2,5}(:[0-9]{1,5})?(/.*)?)$";
@Column(name = "url", length = 256, nullable = false)
private String value;
public Url(String fullUrl) {
if (!this.isValidUrl(fullUrl)) {
throw new InternalLogicException(ErrorCode.DOMAIN_CANNOT_CREATE);
}
this.value = fullUrl;
}
private boolean isValidUrl(String fullUrl) {
return !Objects.isNull(fullUrl) && patternMatches(fullUrl, REGEX_PATTERN);
}
private boolean patternMatches(String targetUrl, String regexPattern) {
return Pattern.compile(regexPattern)
.matcher(targetUrl)
.matches();
}
}
바로 Pattern.compile()이 매번 인스턴스를 생성하고 있다는 점이다!
우리의 Scrap 작업에서 (63개의 학과 + 학교 전체 7개의 카테고리)를 스크랩하고 URL을 검증하고 영속화한다.
이러한 객체들이 5분 단위로 계속 70개씩 축적되어 비교적 짧은 시간 안에 많은 메모리를 잡아먹게 된 것이다.
4-1) 해결하기
해결방법은 간단했다!
매번 compile()하는 것 이 아니라, 미리 compiled 된 대상과 match 하는 것이다.
private static final Pattern compiledUrlPattern = Pattern.compile(REGEX_URL);위와 같이 한번 compile 한 대상과 비교하도록 만들어 주니 더 이상 문제가 발생하지 않았다.
단위 테스트에서도 기능은 정상 동작하여 pass 되었으며... 통합테스트에서도 잘 pass 되었으니...
전혀 의심하지 못했던 것 같다...
5. Before & After 비교
전후의 모니터링 지표들을 살펴보자! 해당 버그를 고치고 배포한 시각은 22시 26분 경이다.
▶ R14 경고가 더 이상 발생하지 않는다.
▶ 줄어든 G1 Eden Heap 메모리
기존에 170MB 정도 사용한 점(32%)에 비하여, 약 47MB로(9%) 많은 메모리를 낭비하지 않게 될 수 있었다!!
▶ Heroku 보드에서 확인한, 줄어든 Heap 메모리
이상으로 항상 메모리 조심하자!