문제의 발생 - Memory Leak
시스템의 계층화된 아키턱처의 구조로 볼 때, Persistence Layer (또는 Data Access Layer)의 경우 "iBatis + iBatis DAO"를 사용하여 구현되었는데, 어느 시점에서 간간이 예의 OOM(OutOfMemory) 에러가 발생했다. 런타임이 지속될수록 어플리케이션의 응답속도가 현저하게 떨어지는 증상이 나타났는데, 어딘가에 Memory Leak(메모리 누수)가 있음이 분명했다.
참고로 iBatis의 정확한 버전은 2.1.6 build# 592 이다. 개발할 당시 최신 버전은 2.3.0 이었는데, 좀더 검증되고 레퍼런스가 많은 버전을 선택했었다.
우선 문제가 발생한 시점을 전후로 변경된 코드 내역들에 대해서 검토하고, 각 계층(특히 Service Layer와 Persistence Layer)에 있어서 base code(class)의 기본적인 프로세스(Life Cycle)를 다시 리뷰하면서 문제 코드에 대한 범위를 좁혀갔다.
다행히 손쉽게 심증이 가는 부분을 찾을 수 있었지만 정확한 원인(물증 :)을 파악할 필요가 있었기 때문에, 기본적으로 GC 로그를 모니터링하고 APM(Application Performance Management) 및 Profiler 툴을 활용하여 문제 영역에 접근해보기로 했다. 사실, 문제 해결보다는 제니퍼를 사용해본 경험이 전무하여 툴을 활용해보고 싶은 마음이 더 강했는지도 모르겠다. ^^; 아무튼 Jennifer와 JProfiler 평가판을 다운로드하였다. 제니퍼는 설치 및 사용에 대한 문서가 간략하고 잘 정리되어 있어 쉽게 설치할 수 있었다.
- APM: Jennifer 3.2 (2주 평가판)
- Profiler: JProfiler 5.1 (10일 평가판)
Test 및 결과 요약
테스트 프로그램들을 작성하고 언급한 툴들을 활용하여 결과를 모니터링하였다. 프로그램은 쓰레드로 작성되었으며, 시작 버튼을 누르면 종료 버튼을 누르기 전까지 무한히 서비스를 호출하도록 하였다. 테스트는 개발 환경과 동일한 구성을 갖고 있는 1G 메모리(RAM)의 내 극빈한 M1 노트북에서 실행하였다.
자세한 상황과 과정을 모두 설명하기는 힘들지만, 대강 결론부터 얘기하자면 BaseService 에서 해당 작업을 종료할 때 호출하는 logging 메서드(작업에 대한 사용자 행위 추적을 구현) 부분에서부터 문제가 시작되었다.
BaseService에 대해 부연하자면, 모든 business logic을 구현하는 서비스들은 BaseServcie 클래스를 상속하도록 되어 있다. Controller와 유사한 역할을 한다고 봐도 무방할 듯 하다. UI(JNLP 클라이언트)에서 사용자의 액션 및 이벤트 등에 의해 발생하는 모든 서버 단 호출(Service Call)의 경우 호출 종료와 동시에 BaseServcie에 의해 logging 메서드가 호출된다. 하나의 이벤트에 의해 호출되는 서비스가 하나 이상이 될 수 있으므로 이 메서드는 호출 빈도수가 매우 높은 편에 속한다.
테스트 프로그램을 시작하면 BaseServcie 를 상속하는 서비스를 호출하게 되고 동시에 계속해서 logging 메서드가 호출되게 된다.
logging 메서드 호출부를 포함한 상태에서 테스트 프로그램을 실행하고 제니퍼로 모니터 하였다. 아래 그림은 문제 상황에서 제니퍼를 사용하여 메모리의 추이를 지켜본 것이다.
heap 사이즈가 지속적으로 증가하고 있다. 우측에서 갑자기 떨어지는 부분은 종료 버튼을 눌러 테스트 프로그램의 쓰레드를 중단하던 순간인데 이것은 무시해도 좋을 것 같다. 아무튼 상황이 심각해서 쓰레드를 종료하지 않으면 계속 프로그램을 실행하면 나중에는 노트북이 먹통(CPU 100%)이 될 정도록 버벅거렸다.
참고로 로컬에서 돌아가는 WAS(JEUS)의 VM 옵션은 다음과 같다.
<command-option>
-Xms512m -Xmx512m -XX:NewSize=128m -XX:MaxNewSize=128m -XX:PermSize=128m -XX:MaxPermSize=128m
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:D:\gc.log
-server
</command-option>
-Xms512m -Xmx512m -XX:NewSize=128m -XX:MaxNewSize=128m -XX:PermSize=128m -XX:MaxPermSize=128m
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:D:\gc.log
-server
</command-option>
다음 그림은 위 그림과 동일한 시점에서의 GC로그 콘솔을 캡처한 화면이다.
minor GC가 꾸준히 발생하다가 Full GC가 지속적으로 발생하였다. 화면의 경우 Full GC가 발생한 직후 캡처한 것인데, 최초 Full GC의 경우 14초 이상 소요되는 것을 확인할 수 있다.
Full GC의 경우 속도가 느리고 GC가 일어나는 과정에서 thread가 중지되어 어플리케이션이 멈춰 버리기 때문에 성능과 안정성에 큰 영향을 준다. 위와 같이 Full GC가 지속적으로 발생되는 것만으로도 결국 그만큼 프로그램의 응답 속도가 현저하게 느려지는 결과를 초래하였다. 이것이 시간이 지날 수록 어플리케이션이 느려지는 주요한 원인이 되었다.
다음으로 아래 그림은 테스트 프로그램에서 logging 메서드 호출부를 뺀 상태에서 테스트한 것이다.
다음은 동일한 조건과 시점에서의 GC 로그이다.
다소 안정되어 보인다.
원인 분석과 소스 수정
어플리케이션 실행 중 heap 상에 존재하는 객체들(실제 메모리의 Collection 및 Object들)을 대상으로 메모리 누수와 연관된 객체를 파악할 수 있다면 보다 확실하게 문제 코드에 접근할 수 있을텐데, 제니퍼 세팅이 잘못 되었는지 유일하게 Collelction에 대한 실시간 모니터링만 되지 않았다. 대신 JProfiler를 사용해서 확인하였는데, 아래 그림이 해당 화면을 캡처한 것이다.
그림으로는 잘 보이지않지만 java.lang.String 타입의 instance count가 1,496,688이고 char[] 배열 타입은 1,423,882개로 나타난니다. 이 둘(문자열)을 합친 메모리만 200M를 웃돌고 있다.
여기서 다시 메소드를 조사해보았다.
선택된 부분을 확대해서 보면 다음과 같다.
트리에서 선택된 노드는 LoggingService2.logging 메서드이며, 이것은 BaseService의 logging에 의해 호출된다. LoggingService2.logging의 두 단계 아래 노드를 보면 "DaoManagerBuilder.buildDaoManager" 메서드를 확인할 수 있다.
LoggingService2에는 DB에 로그 데이터를 기록하기 위해 DaoCofig로부터 DaoManager를 가져오는 부분을 필수로 포함하고 있다.
DaoManager daoManager = DaoConfig.newDaoManager(DaoResource.JobResName);
상단의 코드에 기술된 DaoConfig 및 newDaoManager 등의 코드는 iBatis의 예제 코드인 JPetStore의 소스 중 동일한 이름의 클래스를 참고하였는데, 이 코드의 전체는 하단과 같다. 프로젝트에서 사용한 newDaoManager 메서드의 코드 블럭은 이 예제와 거의 동일하였다.
package com.ibatis.jpetstore.persistence;
import com.ibatis.common.jdbc.ScriptRunner;
import com.ibatis.common.resources.Resources;
import com.ibatis.dao.client.DaoManager;
import com.ibatis.dao.client.DaoManagerBuilder;
import java.io.Reader;
import java.sql.Connection;
import java.sql.DriverManager;
import java.util.Properties;
public class DaoConfig {
private static final String resource = "com/ibatis/jpetstore/persistence/dao.xml";
private static final DaoManager daoManager;
static {
try {
daoManager = newDaoManager(null);
Properties props = Resources.getResourceAsProperties("properties/database.properties");
String url = props.getProperty("url");
String driver = props.getProperty("driver");
String username = props.getProperty("username");
String password = props.getProperty("password");
if (url.equals("jdbc:hsqldb:mem:jpetstore")) {
Class.forName(driver).newInstance();
Connection conn = DriverManager.getConnection(url, username, password);
try {
ScriptRunner runner = new ScriptRunner(conn, false, false);
runner.setErrorLogWriter(null);
runner.setLogWriter(null);
runner.runScript(Resources.getResourceAsReader("ddl/hsql/jpetstore-hsqldb-schema.sql"));
runner.runScript(Resources.getResourceAsReader("ddl/hsql/jpetstore-hsqldb-dataload.sql"));
} finally {
conn.close();
}
}
} catch (Exception e) {
throw new RuntimeException("Description. Cause: " + e, e);
}
}
public static DaoManager getDaoManager() {
return daoManager;
}
public static DaoManager newDaoManager(Properties props) {
try {
Reader reader = Resources.getResourceAsReader(resource);
return DaoManagerBuilder.buildDaoManager(reader, props);
} catch (Exception e) {
throw new RuntimeException("Could not initialize DaoConfig. Cause: " + e, e);
}
}
}
JPetStore 예제에서는 getDaoManager()를 사용하여 정적으로 초기화된 단 하나의 DaoManager를 사용했지만, 프로젝트에서는 서브 시스템별로 dao.xml을 정의하고 각 시스템별로 달리 DaoManager를 사용하였으므로 모든 서비스 코드에서는 위에 기술한 바와 같이 DaoConfig의 newDaoManager() 메서드를 통하여 daoManager 인스턴스를 초기화하여 사용하였다.
import com.ibatis.common.jdbc.ScriptRunner;
import com.ibatis.common.resources.Resources;
import com.ibatis.dao.client.DaoManager;
import com.ibatis.dao.client.DaoManagerBuilder;
import java.io.Reader;
import java.sql.Connection;
import java.sql.DriverManager;
import java.util.Properties;
public class DaoConfig {
private static final String resource = "com/ibatis/jpetstore/persistence/dao.xml";
private static final DaoManager daoManager;
static {
try {
daoManager = newDaoManager(null);
Properties props = Resources.getResourceAsProperties("properties/database.properties");
String url = props.getProperty("url");
String driver = props.getProperty("driver");
String username = props.getProperty("username");
String password = props.getProperty("password");
if (url.equals("jdbc:hsqldb:mem:jpetstore")) {
Class.forName(driver).newInstance();
Connection conn = DriverManager.getConnection(url, username, password);
try {
ScriptRunner runner = new ScriptRunner(conn, false, false);
runner.setErrorLogWriter(null);
runner.setLogWriter(null);
runner.runScript(Resources.getResourceAsReader("ddl/hsql/jpetstore-hsqldb-schema.sql"));
runner.runScript(Resources.getResourceAsReader("ddl/hsql/jpetstore-hsqldb-dataload.sql"));
} finally {
conn.close();
}
}
} catch (Exception e) {
throw new RuntimeException("Description. Cause: " + e, e);
}
}
public static DaoManager getDaoManager() {
return daoManager;
}
public static DaoManager newDaoManager(Properties props) {
try {
Reader reader = Resources.getResourceAsReader(resource);
return DaoManagerBuilder.buildDaoManager(reader, props);
} catch (Exception e) {
throw new RuntimeException("Could not initialize DaoConfig. Cause: " + e, e);
}
}
}
JPetStore 예제에서는 getDaoManager()를 사용하여 정적으로 초기화된 단 하나의 DaoManager를 사용했지만, 프로젝트에서는 서브 시스템별로 dao.xml을 정의하고 각 시스템별로 달리 DaoManager를 사용하였으므로 모든 서비스 코드에서는 위에 기술한 바와 같이 DaoConfig의 newDaoManager() 메서드를 통하여 daoManager 인스턴스를 초기화하여 사용하였다.
public class SomeService extends BaseService {
private DaoManager daoManager;
private SomeDAO someDao;
private DaoManager daoManager;
private SomeDAO someDao;
public SomeService() {
daoManager = DaoConfig.newDaoManager(DaoResource.JobResName);
this.someDao = (SomeDAO) daoManager.getDao(SomeDAO.class);
}
...
}
참고로 BaseService 유형의 클래스들은 Servlet이 Container에 의해 관리되듯이 단 하나의 인스턴스로 존재한다.
여기서 잠시 iBatis DAO와 관련된 내용에 대해 언급하자면, iBatis DAO 프레임워크를 초기화하기 위해서는 dao.xml 파일 경로를 파라미터로 넘겨주어 DaoManagerBuilder.buildDaoManager()를 호출해야한다. DAO 프레임워크는 이 메서드에서 해당 dao.xml 파일을 읽고 상응하는 DaoManager를 생성하게된다. client는 이 DaoManger를 사용하여 insert 등과 같은 제반 작업을 수행하게 된다. 아래 그림을 참고하면 된다.
DAO sequence diagram (그림 참고)
앞서 설명했듯이, 테스트 프로그램은 문제 상황을 빨리 발생시키기 위해서 무한하게 트랜잭션을 발생시키는 형태를 취했지만 logging 메서드 자체가 매우 빈번하게 호출되는 구조임을 전제로 하고 생각해 볼 때,
일반적으로 특정 메서드의 블럭을 벗어나게 되면 메서드 내에서 지역변수로 사용한 객체는 Garbage Collection의 대상이 대상이 된다. 하지만, 설명한 바와 같이 DaoManagerBuilder.buildDaoManager()에서 dao.xml 파일에 대한 I/O가 일어나고 읽어들인 파일을 parsing하고 DaoManager의 인스턴스를 생성하는 작업을 수행하게 되는데, 결과로 미루어 볼때 어느 정도 시간 간격을 둔 상태에서는 별 무리 없이 수행되었지만, logging과 같이 짧은 시간에 많은 수의 서비스를 수행과 동시에 호출되는 경우 GC가 제대로 되지 못하고 결국 감당을 하지 못하게 되는 듯 하다. 추측컨데, JProfiler에서 보여진 수많은 문자열 관련 객체들은 반복되는 I/O와 parsing 작업의 부산물이라 여겨졌다.
이것이 원인이 맞다면, DaoManager를 초기화 하기 위해 매번 DaoConfig의 newDaoManager를 호출함으로써 빈번한 buildDaoManager 작업을 발생시킬 수 있는 개연성을 갖는 것을 미연에 방지하기 위해 DaoConfig 자체를 수정하는 것이 좋을 듯 했다.
따라서 근본적인 원인을 제공한 DaoConfig의 소스를 아래 코드와 같이 수정한 후 다시 프로그램을 실행하였다. DaoConfig는 싱글톤(singleton)으로 변경하고 각 업무단의 DaoManager를 Hashtable을 사용하여 cache 하도록 수정하였다. 캐슁으로 인한 부작용(?!)은 없을까 잠시 생각해보았는데 dao.xml을 리로드하기 위해서는 어차피 WAS를 재시작할 필요가 있었다. SQL Map 파일의 경우 절대 경로를 사용하여 자동으로 다시 로드 되게끔 되어 있다(개발서버의 경우만 해당).
다음이 대강의 코드이다.
public class DaoConfig {
private static DaoConfig instance = null;
private static Hashtable<String, DaoManager> daoManagers = null;
private DaoConfig() {
daoManagers = new Hashtable<String, DaoManager>();
}
public static DaoConfig getInstance() {
if (instance == null) {
instance = new DaoConfig();
}
return instance;
}
public DaoManager getDaoManager(String resource, Properties props) {
DaoManager daoManager = null;
if (daoManagers.containsKey(resource)) {
daoManager = (DaoManager) daoManagers.get(resource);
}
else {
try {
Reader reader = Resources.getResourceAsReader(resource);
daoManager = DaoManagerBuilder.buildDaoManager(reader, props);
daoManagers.put(resource, daoManager);
} catch (Exception e) {
throw new RuntimeException("DaoConfig를 초기화할 수 없습니다. 원인: " + e, e);
}
}
return daoManager;
}
/* 호환성을 위해 남겨둔 method들 */
public static DaoManager newDaoManager(String resource) {
return newDaoManager(resource, null);
}
public static DaoManager newDaoManager(String resource, Properties props) {
DaoConfig config = DaoConfig.getInstance();
return config.getDaoManager(resource, props);
}
}
다시 프로그램을 실행하고 결과를 보여주는 제니퍼 화면을 캡처 하였다. 비교를 위해 이전의 화면들을 다시 붙였다. 수정된 코드가 반영된 결과 화면은 마지막 화면이다.private static DaoConfig instance = null;
private static Hashtable<String, DaoManager> daoManagers = null;
private DaoConfig() {
daoManagers = new Hashtable<String, DaoManager>();
}
public static DaoConfig getInstance() {
if (instance == null) {
instance = new DaoConfig();
}
return instance;
}
public DaoManager getDaoManager(String resource, Properties props) {
DaoManager daoManager = null;
if (daoManagers.containsKey(resource)) {
daoManager = (DaoManager) daoManagers.get(resource);
}
else {
try {
Reader reader = Resources.getResourceAsReader(resource);
daoManager = DaoManagerBuilder.buildDaoManager(reader, props);
daoManagers.put(resource, daoManager);
} catch (Exception e) {
throw new RuntimeException("DaoConfig를 초기화할 수 없습니다. 원인: " + e, e);
}
}
return daoManager;
}
/* 호환성을 위해 남겨둔 method들 */
public static DaoManager newDaoManager(String resource) {
return newDaoManager(resource, null);
}
public static DaoManager newDaoManager(String resource, Properties props) {
DaoConfig config = DaoConfig.getInstance();
return config.getDaoManager(resource, props);
}
}
* 최초의 문제가 있던 상태
* logging 메서드를 호출하지 않은 상태
* DaoConfig를 수정한 이후 상태
훨씬 안정적인 상태로 변했다.
이 상태에서의 GC 로그는 다음과 같다.
결론적으로 DaoManager를 각각의 서비스 코드에서 매번 초기화하기 위해서 DaoConfig의 newDaoManager 메서드를 호출할 때, 빈번한 DaoManagerBuilder.buildDaoManager()가 호출되는 구조는 문제를 일으킬 여지가 있는 것 같다.
대강 정리를 마치고 내용을 한번 읽어보았는데, 정리가 제대로 된 것 같지는 않다. ^^;
아무튼 요는, 항상 기본에 충실하고 미리 생각하는 개발자가 되자! ^^
P.S. 잘못된 내용이 있다면 지적 바랍니다. ^^
참고
관련 API
- http://ibatis.apache.org/docs/java/dev/com/ibatis/dao/client/DaoManager.html
- http://ibatis.apache.org/docs/java/dev/com/ibatis/dao/client/DaoManagerBuilder.html
- http://ibatis.apache.org/docs/java/dev/com/ibatis/dao/engine/builder/xml/XmlDaoManagerBuilder.html
- http://kickjava.com/src/com/ibatis/dao/client/DaoManagerBuilder.java.htm
- http://kickjava.com/src/com/ibatis/dao/engine/builder/xml/XmlDaoManagerBuilder.java.htm
Posted by Mr.朴
