주말에 갑자기 서버가 죽었었다. 노트북을 가지고 있지 않았어서 우선 급한대로 서버를 재기동 시켰다.
AWS CloudWatch 를 확인해보니 out of memory 로 인해서 그런듯 보였다.
우선 기존에 JVM option 으로 -XX:+HeapDumpOnOutOfMemoryError 를 추가해 놓았기 때문에 힙덤프를 떠 놓았겠지 싶었다. 그러나 베스천 서버를 통해 ec2 서버에 접속해보니 힙덤프 로그는 보이지 않았다. 한 가지 추가하지 않은 것이 있다면 -XX:HeapDumpPath 해당 옵션을 추가하지 않았다. 옵션이 없어도 기본적으로 JVM 시작 디렉토리에 저장이 된다고는 하지만 난 ec2 내에서 찾지 못했다(출처: 권남의 블로그).
어쨌든 서버가 죽었으니 원인을 파악해야 했다. ec2 장비에 접속해서 top 을 이용해 메모리를 얼마나 먹고 있는지 계속 실시간으로 모니터링 했다. 물론 top 명령어가 실행 중인 java process 의 heap memory 에 대해서는 알 수가 없다. 또한, 내부적으로 GC 가 일어날 수도 있기에 단순히 현재 java process 가 먹고 있는 메모리로 판단하면 안된다. 그러나 나는 나중에 예기치 못한 상황에 다시 서버가 죽게 되는 상황으로 인해 힙덤프를 뜨지 못할까봐 우선 top 을 통해 내가 설정한 xmx 메모리에 0.7만큼 메모리가 찼을 때 힙덤프를 떴다. 그리고 원래라면 실서버 운영 중인 ec2 에서 힙덤프를 뜨면 절대 안된다. 힙덤프 뜨는 작업으로 인해 요청이 제대로 동작하지 않기 때문이다. 그러나 우선은 서버에 요청이 아예 없을 뿐더러 AWS EB 에서 알아서 ec2 상태를 판단하여 다른 서버로 요청을 보내기에 힙덤프를 뜨기로 정했다.
어찌되었든 약 1시간동안 힙덤프를 떴고 scp 를 이용하여 내 로컬까지 무사히 옮겼다.
jmap 을 이용해 힙덤프를 까보니 다음과 같이 어디선가 메모리를 1.1GB 나 먹고 있었다.
그리고 확인해보니 QueryPlanCache 라는 객체에서 1.1GB 나 먹고 있었던 것이다. 보자마자 Cache 라는 네이밍으로 보아서 이 부분에 문제가 있었던게 틀림 없었다. 따로 entity 캐싱을 하지 않기 때문이었다.
우선 내가 직접 디버깅 했을 때 QueryPlanCache 는 다음과 같다.
메소드 파라미터로 queryString 이 존재하는데, 이 때 criteria query 가 인자로 들어온다. 그리고 아래 사진과 같이 queryPlanCache 에 데이터가 존재하면 넘기고 그렇지 않으면 QueryPlan 을 생성하여 QueryPlanCache 에 넣고 반환한다. 제일 위에서 HQLQueryPlanKey 객체를 생성 후 queryPlanCache.get(key) 를 하는데 이 때는 오브젝트 hash 값을 이용하여 하는 것으로 보인다.
HQLQueryPlan 를 보았을 때 아래 사진과 같은 값이 들어있다. 내부적으로 AST 를 이용하여 실제 sql 을 만드는 듯 보였다.
사진에 보이는 sql 변수에 실제 sql 이 들어있다.
결과적으로 위에 이유로 인해서 캐싱을 하는 것 같다. 거의 모든 쿼리에 대하서 캐싱하기 때문에 순식간에 캐싱된 쿼리가 아래 사진과 같이 82개가 쌓인 것을 볼 수 있다. 이렇게 쿼리를 모두 캐싱하기 때문에 메모리를 저렇게 먹었던 것으로 보인다(조건에 대한 값까지는 :studentID 이런 식으로 쿼리가 작성 돼 있기 때문에 조건 값까지는 캐싱을 하지 않는다).
이렇게까지 캐싱을 하는데 default 로 잡혀있는 query plan max count 가 2048개이다 (2048MB 가 아니니 참고하자).
어쨌든 우리는 이렇게 매 쿼리들을 캐싱한다는 것을 알았다.
나는 우선 위 2048개로 설정된 값을 줄여서 변경하여 배포했다. 몇 주동안 잠잠한 것을 보니 성공한 것으로 보인다.