Situaction
지난 포스팅에서는 회사에서 옵저버빌리티 시스템을 구축했다는 이야기와 함께 MDC와 TaskDecorator를 활용하여 로그 수집을 개선한 이야기를 다루었다. 그 이후에도 (직접 설계하고 구축해서 그런지) Grafana 대시보드에 애정을 가지고 자주 살펴보고 있었다.
그렇게 6월 한달간 꾸준히 살펴보며 각 수치의 크리티컬한 기준을 세우고, Grafana Alert Manager를 통해 장애 감지 Alert Rule을 설정하던 중 이상한 것? 수치?를 발견하였다. 바로 각 서버들의 Heap 사용량이다. 현재 관측하고 있는 서버는 총 다섯대인데, 그 중 두 서버의 Heap 사용량이 꽤나 높게 측정되었다.
왜? 이 두 서버만 계속 알림이 뜨지? 다행히도 머지 않아 Resolve 되었다는 알림이 추가로 울렸다. 또, 일주일 간 계속 관측했을 때 Heap 사용률이 90%를 넘지 않고, 그 전에 모두 Resolve가 되었음을 확인하고 GC가 잘 수행되고 있음을 예측할 수 있었다. 하지만 다른 서버들은 30% 주변을 맴도는데 이 두 서버는 최소 55%의 수치를 보여주고 있다는건 어딘게 문제가 있다는 뜻이기에 그냥 넘어가지 않고 한번 파헤쳐보기로 결정했다.
Task
1. GC가 수행돼도 Heap 사용량이 줄어들지 않는가?
위에서 Resolve 알림을 보고 GC가 잘 이루어지고 있다고 가정하였다. 하지만 이건 가정일뿐, 당연히 가시적인 증명이 필요하다. 따라서 Grafana 대시보드를 통해 수치를 확인해보았다.
Eden Space: 새로 생성된 객체가 할당되는 Heap 내부 영역
Eden Space 영역과 GC Count를 통해 GC가 잘 이루어지는지 간단하게 확인할 수 있었다. 특히 Eden Space 영역의 메모리 사용량 그래프는 정말 이쁘게(?) 그려져 있었다.
이를 통해 GC가 수행돼도 Heap 사용량이 줄어들지 않는가?에 대한 답변은 X 로 판단되었다.
2. Memory Leak는 어디에서 발생했는가?
GC가 발생해도 Heap 사용량이 많다는 것은 메모리 누수(Memory Leak)가 발생했다는 것이다. 메모리 누수가 발생할 수 있는 원인은 여러가지가 있는데, 이를 확인하기 위해 프로젝트 코드를 모두 뜯어본다는건 쉽지 않은 일이다. 그래서 이를 도와주기 위해 우리가 Java를 활용할 때 꾸준히 듣던 JDK에서 관련된 많은 도구들을 제공해주고 있다.
JDK: Java Development Kit
Heap Dump 생성하기
Heap을 확인하는 여러 방법이 있겠지만, 나는 Heap Dump를 통해 분석하기로 결정했다.
$ jps
7687 Jps
64854 Application 먼저 jps 명령어를 통해 현재 JVM 프로세스 목록을 조회할 수 있다. Application의 PID를 확인했으니 이제 Heap Dump 파일을 생성해보자. Heap Dump 파일은 일반적으로 .hprof 확장자를 사용한다.
$ jmap -dump:file=application.hprof 64854 jmap 명령어를 통해 Heap Dump 파일을 생성할 수 있다. 이렇게 생성된 Heap Dump 파일은 운영하고 있는 서버 인스턴스에 존재하므로, scp 명령어를 통해 로컬로 옮겨주면 되고, 나는 이 Dump 파일은 Eclipse Memory Analyzer(이하 MAT)를 활용하여 분석하였다.
Heap Dump 분석하기
MAT를 통해 Heap Dump 파일을 분석하면 위와 같은 도표를 확인할 수 있다. 현재 (a)와 (b)가 Problem Suspect 영역으로 보이는데, 이 부분을 중점적으로 살펴보면 문제를 해결할 수 있다.
그런데 예상치 못한 문제를 발견할 수 있었다. 프로젝트 소스코드에 메모리 누수의 원인이 있을거라 생각했는데 MySQL Connection과 관련된 내용이 기재되어 있었다. 자세히 살펴보니 공통적으로 abandoned connection cleanup이라는 키워드를 도출 할 수 있었다. 그렇다면 AbandonedConnectionCleanupThread는 무엇이고, 어떤게 문제였을까?
3. AbandonedConnectionCleanupThread를 막아라
AbandonedConnectionCleanupThread, 너 누군데?
문제를 해결하기 위해선 AbandonedConnectionCleanupThread가 무엇인지 먼저 알 필요가 있다. AbandonedConnectionCleanupThread.java의 최상단 주석에는 다음과 같은 description 주석이 있다.
- This class implements a thread that is responsible for closing abandoned MySQL connections, i.e., connections that are not explicitly closed.
- There is only one instance of this class and there is a single thread to do this task. This thread's executor is statically referenced in this same class.
이를 해석하여 정리해보면 다음과 같다.
- AbandonedConnectionCleanupThread: 명시적으로
닫히지 않은 MySQL 커넥션(abandoned connections)을 닫아주는 역할 - 인스턴스는 오직 하나만 생성되며, 이 작업을 수행하는 스레드도 단 하나
- 이 스레드를 실행하는 executor는 이 클래스 내에 static 필드로 참조되어 있음
Spring Boot 2.0부터는 Default Connection Pool로 사용되는 HikariCP를 활용하고 있다. 현재 프로젝트에서도 교체 없이 HikariCP를 활용하고 있기 때문에 Connection을 개발자들이 직접 생성 및 관리하는 경우는 현재는 없다. 그렇다 하더라도 AbandonedConnectionCleanupThread 녀석, 설명만 보면 참 좋은 녀석인 것 같은데, 왜 말썽일까? 이것 또한 설명을 보고 눈치 챈 사람들이 있을 것 같다. 바로 오직 하나만 생성되고, 작업 수행 또한 하나의 스레드만 해서이다. 이 내용을 내부 코드를 통해 살펴보자.
AbandonedConnectionCleanupThread.java
public class AbandonedConnectionCleanupThread implements Runnable {
// 생략
static {
if (abandonedConnectionCleanupDisabled) {
cleanupThreadExecutorService = null;
} else {
cleanupThreadExecutorService = Executors.newSingleThreadExecutor(r -> {
Thread t = new Thread(r, "mysql-cj-abandoned-connection-cleanup");
t.setDaemon(true);
ClassLoader classLoader = AbandonedConnectionCleanupThread.class.getClassLoader();
if (classLoader == null) {
classLoader = ClassLoader.getSystemClassLoader();
}
t.setContextClassLoader(classLoader);
return threadRef = t;
});
cleanupThreadExecutorService.execute(new AbandonedConnectionCleanupThread());
}
}
. . .위 코드는 AbandonedConnectionCleanupThread의 내부 코드다. static 블럭을 보면 AbandonedConnectionCleanupThread는 newSingleThreadExecutor에 의해 단일 스레드로 실행됨을 알 수 있다. 다음 코드를 이어서 보자.
// 생략
public void run() {
for (;;) {
try {
checkThreadContextClassLoader();
Reference<? extends MysqlConnection> reference = referenceQueue.remove(5000);
if (reference != null) {
finalizeResource((ConnectionFinalizerPhantomReference) reference);
}
} catch (InterruptedException e) {
threadRefLock.lock();
try {
threadRef = null;
Reference<? extends MysqlConnection> reference;
while ((reference = referenceQueue.poll()) != null) {
finalizeResource((ConnectionFinalizerPhantomReference) reference);
}
connectionFinalizerPhantomRefs.clear();
} finally {
threadRefLock.unlock();
}
return;
} catch (Exception ex) {
// Nowhere to really log this.
}
}
}
. . . Runnable을 implements하고 있는 AbandonedConnectionCleanupThread에서 구현한 run() 메서드다. referenceQueue의 remove() 메서드를 통해 NetworkResources를 필드로 가지고 있는 PhantomReference<MysqlConnection>를 상속하고 있는 ConnectionFinalizerPhantomReference를 가져오고 있다. 그 이후에는 finalizeResource() 메서드를 호출하고 있는데, 아래 간단한 설명을 살펴보고 다음 코드를 살펴보자.
ReferenceQueue의 remove() 메서드는 내부적으로poll()을 수행하도록 코드가 작성돼있다.PhantomReference: GC가 참조하는 실제 객체가 더 이상 필요하지 않아 회수할 수 있다고 판단한 후에 ReferenceQueue에 들어가는 객체
// 생략
private static void finalizeResource(ConnectionFinalizerPhantomReference reference) {
try {
reference.finalizeResources();
reference.clear();
} finally {
connectionFinalizerPhantomRefs.remove(reference);
}
}
private static class ConnectionFinalizerPhantomReference extends PhantomReference<MysqlConnection> {
private NetworkResources networkResources;
ConnectionFinalizerPhantomReference(MysqlConnection conn, NetworkResources networkResources, ReferenceQueue<? super MysqlConnection> refQueue) {
super(conn, refQueue);
this.networkResources = networkResources;
}
void finalizeResources() {
if (this.networkResources != null) {
try {
this.networkResources.forceClose();
} finally {
this.networkResources = null;
}
}
}
}
} finalizeResource() 메서드에서는 ConnectionFinalizerPhantomReference의 finalizeResources() 메서드를 호출하여 NetworkResources를 forceClose() 한 후 null을 할당하고 있다.
간단하게 정리해보면 AbandonedConnectionCleanupThread는 닫히지 않은 MySQL 커넥션을 닫아주기 위해 한번에 한개의 PhantomReference를 꺼내와 NetworkResources를 종료 시켜주고 있다. 그럼 한번에 한개의 NetworkResources를 종료시켜주기 때문에 병목이 발생한 것일까? 다음 코드를 확인해보자.
public class NetworkResources {
private final Socket mysqlConnection;
private final InputStream mysqlInput;
private final OutputStream mysqlOutput;
// 생략
public final void forceClose() {
try {
if (!ExportControlled.isSSLEstablished(this.mysqlConnection)) {
try {
if (this.mysqlInput != null) {
this.mysqlInput.close();
}
} finally {
if (this.mysqlConnection != null && !this.mysqlConnection.isClosed() && !this.mysqlConnection.isInputShutdown()) {
try {
this.mysqlConnection.shutdownInput();
} catch (UnsupportedOperationException e) {
// Ignore, some sockets do not support this method.
}
}
}
}
} catch (IOException e) {
// Can't do anything constructive about this.
}
try {
if (!ExportControlled.isSSLEstablished(this.mysqlConnection)) {
try {
if (this.mysqlOutput != null) {
this.mysqlOutput.close();
}
} finally {
if (this.mysqlConnection != null && !this.mysqlConnection.isClosed() && !this.mysqlConnection.isOutputShutdown()) {
try {
this.mysqlConnection.shutdownOutput();
} catch (UnsupportedOperationException e) {
// Ignore, some sockets do not support this method.
}
}
}
}
} catch (IOException e) {
// Can't do anything constructive about this.
}
try {
if (this.mysqlConnection != null) {
this.mysqlConnection.close();
}
} catch (IOException e) {
// Can't do anything constructive about this.
}
}
}
NetworkResources의 forceClose() 메서드에서는 입출력 스트림을 종료하고, 마지막으로 MySQL Connection 소켓을 닫아주고 있다. 따라서 네트워크 환경에 따라 병목이 발생할 수 있고, 더군다나 한번에 한개의 커넥션을 정리하기에 병목의 위험성은 더 높을 수밖에 없다.
HikariCP의 max-lifetime
문제가 있던 서버들은 공통점이 있다. 바로 max-lifetime을 짧게 지정돼있다는 점이다. 초기 스타트업 특성상 큰 규모의 회사보다 배포 주기가 짧고, 특히 개발 서버의 배포는 하루에도 수십번 이루어질 수 있다. 이 때 다음과 같은 문제가 발생할 수 있다.
무중단 배포를 진행하면서 MySQL에 "Sleep" 상태의 커넥션이 남아있을 수 있다는 것이다. 따라서 HikariCP의 디폴트 max-liftime(30분)이 아닌 짧은 주기로 설정해두었다. 이러한 설정은 개발 환경뿐만 아니라 운영 환경에도 추가돼있고, 이 때문에 병목이 발생하여 AbandonedConnectionCleanupThread에 AbandonedConnection이 계속 쌓이는 현상이 발생했던 것이다.
Action
이를 해결하기 위해 두 가지 해결방법을 고려해볼 수 있다.
HikariCP의 max-lifetime 조정
가장 간단한 방법은 HikariCP의 max-lifetime을 다시 길게 조정하는 것이다. 하다못해 디폴트 값인 30분으로 지정해놓으면 AbandonedConnection이 쌓이는 속도가 느리기 때문에 문제가 발생하지 않을 것이다. 하지만 이 방법은 프로젝트에서 HikariCP의 max-lifetime을 짧게 설정했던 이유를 거스르는 방법이다.
2020-02-20 03:16:23 - HikariPool-1 - Failed to validate connection
com.mysql.cj.jdbc.ConnectionImpl@1d4190c8 (No operations allowed after connection closed.).
Possibly consider using a shorter maxLifetime value.
2020-02-20 03:16:28 - HikariPool-1 - Failed to validate connection
com.mysql.cj.jdbc.ConnectionImpl@235a8c16 (No operations allowed after connection closed.).
Possibly consider using a shorter maxLifetime value.
2020-02-20 03:16:33 - HikariPool-1 - Failed to validate connection
com.mysql.cj.jdbc.ConnectionImpl@61538516 (No operations allowed after connection closed.).
Possibly consider using a shorter maxLifetime value.위와 같은 로그를 만날 가능성이 있다.
AbandonedConnectionCleanupThread 비활성화
두번째 방법은 AbandonedConnectionCleanupThread 자체를 비활성화 하는 것이다. 현재 HikariCP를 활용하고 있고, 개발자가 직접 커넥션을 조작할 일이 없다. HikariCP의 HouseKeeper가 커넥션을 알아서 정리해주기 때문에 메모리 누수의 원인인 AbandonedConnectionCleanupThread를 아예 비활성화 하는 것이 좋다고 판단하였다.
- `com.mysql:mysql-connector-j`` 8.0.22 버전 이상 업그레이드
- 자바 실행 옵션에
-Dcom.mysql.cj.disableAbandonedConnectionCleanup=true추가
위와 같이 조치하면 앞서 봤던 AbandonedConnectionCleanupThread의 코드처럼 executor에 null이 할당돼 비활성화 된다.
// 생략
static {
if (abandonedConnectionCleanupDisabled) {
cleanupThreadExecutorService = null;
} else {
// 생략cf) AbandonedConnectionCleanupThread는 왜 deprecated 되지 않았는가
Spring Boot 2.0 이상부터는 DB 커넥션 관리 도구로 HikariCP를 디폴트로 사용하고 있다. 따라서 특수한 경우가 아니라면 AbandonedConnectionCleanupThread는 필요하지 않을 것이다. 그럼에도 존재하는 이유는 레거시 프로젝트와의 호환성 때문이다. 만약 jdbc나 dbcp2 등을 활용하고 있다면 닫히지 않은 커넥션을 닫아주는 중요한 역할을 해줄 것이다.
Result
Heap 사용률이 높아지는 원인은 여러가지가 있을 것이다. 단순히 트래픽이 높아야만 이러한 문제가 발생하는 것은 아니다. 실제로 문제가 있었던 서버들은 트래픽이 낮은 서버들이었다. 실제 장애로 이어지진 않았지만, 사전에 이상함을 감지하고 관련하여 깊게 살펴보면서 해결할 수 있었던 좋은 경험이었다.
해당 레포지토리에 더 많은 이론 및 실습들을 정리하고 있습니다 !
잘봤습니다!