얼마전 특정 사이트의 was에서 oome가 발생하였다. 처음보는 에러에다가 특정 소스의 line이 명확하게 나오지 않아 바로 해결할 수 가 없었다.

맨 처음 발생했을 때 의 oome 메시지는

Exception in thread “main”: java.lang.OutOfMemoryError: Java heap space

구글링 해보니 heap영역의 메모리를 더이상 확보할 수 없다는 의미로 해석이 된다.

그렇다면 heap영역의 크기를 늘리면 되지 않을까? 라는 판단을 하여 heap영역의 크기를 늘리기로 하였다.

heap영역을 늘리기 위해선 tomcat에서 설정을 해야 하는데, $CATALINA_HOME의 bin으로 가면 setenv.sh라는 파일이 있다.(없으며 생성하자.)

<setenv.sh>

#!/bin/sh
export JAVA_OPTS="-Djava.library.path=/usr/local/lib -XX:PermSize=256m -XX:MaxPermSize=1024m -Xms1536m -Xmx1536m -Djava.awt.headless=true"
export LD_LIBRARY_PATH="$LD_LIBRARY_PATH:$CATALINA_HOME/lib:/usr/local/lib"

Xms는 heap의 최소 메모리 즉, 처음 jvm이 실행되었을 때 할당되는 메모리 size이다.

Xmx는 heap이 최대로 사용할 수 있는 메모리 size이다.

32bit의 운영체제에서 jvm은 최대 1.2 ~ 1.5GB 까지만 메모리를 사용할 수 있었기 때문에 1536이라는 수치로 옵션을 설정하게 되었다.

Xms와 Xmx을 동일값으로 부여한 이유는 크기의 동적인 변경에 의한 오버 헤드를 최소화 하기 위함이다.(Sun HotSpt JVM에서 권장)

해당 설정한 이후 약 20일 이후에 다시 oome가 발생하였다.

소스상에 문제가 있는건 아닌가 의문이 들었고 세밀한 분석을 위해, jvm옵션을 더 추가하게 되었다.

#!/bin/sh
export JAVA_OPTS="-Djava.library.path=/usr/local/lib -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/cmuc/tomcat.hprof -XX:PermSize=256m -XX:MaxPermSize=1024m -Xms1536m -Xmx1536m -Djava.awt.headless=true"
export LD_LIBRARY_PATH="$LD_LIBRARY_PATH:$CATALINA_HOME/lib:/usr/local/lib"

추가한 옵션은 -XX:+HeapDumpOnOutOfMemoryError와 -XX:HeapDumpPath=/home/cmuc/tomcat.hprof 

-XX:+HeapDumpOnOutOfMemoryError 옵션은 oome가 발생했을 때 heapdump를 생성하도록 하는 옵션으로

-XX:HeapDumpPath에서 설정한 경로에 heapdump파일을 생성한다.

 

그렇게 생성된 heapdump파일을 이클립스의 MAT로 분석할 수 있는데 소스상에 특별한 문제점은 찾을 수 없었다.

 

그렇다면 GC에 문제가 있는 것일까?라는 의문점을 갖게 되었고,

GC에 대한 정보를 찾다가 네이버 개발자들이 만든 https://d2.naver.com/helloworld/ 의 블로그에서 GC 튜닝관련 정보들을 얻을 수 있었다.

GC튜닝을 하기 전에 먼저 GC가 정상적으로 이루어지는지 확인하기 위해

jvm 명령어인 jstat -gcutil(가비지 컬럭센 통계 데이터의 개요)을 통해 GC 수행 횟수 및 GC 수행하는게 걸리는 시간을 분석할 수 있었다.

<jstat -gcutil의 컬럼 설명>

컬럼명 설명
S0 Young영역의 Survivor 영역 0의 사용률
S1 Young영역의 Survivor 영역 1의 사용률
E Young영역의 Eden영역의 사용률
O Old영역의 사용률
P Permanent 영역의 사용률
YGC Young 영역의 Minor GC 총 수행 횟수
YGCT Young 영역의 Minor GC 총 수행 시간
FGC Old 영역의 Full GC 총 수행 횟수
FGCT Old 영역의 Full GC 총 수행 시간
GCT 전체 GC 총 수행 시간

Minor GC의 평균 수행 시간이 (YGCT/YGC)로 0.5초 미만이면 양호한 상태이다.

Full GC의 평균 수행 시간이 (FGCT/FGC)로 1초 미만이면 양호한 상태이다.

Full GC의 평균 수행 시간이 길 경우 Stop the World 시간이 길어지게 되므로 GC튜닝이나 heap메모리 튜닝이 필요할 것이다. 현재 운용되는 프로세스에서는 모두 양호한 상태이기 때문에 따로 튜닝을 하지 않았다.

 

자.. 그러면 어째서 OOME가 발생하는 것일까..

-----------------------------------------------------------------------------------------------------------------------------------

두 번째 발생했을 때의 로그를 다시 확인해보니

Exception in thread “main”: java.lang.OutOfMemoryError: (Native method) 으로 나오는 것이 확인되었다.

해당 에러는 JVM에 설정된 것 보다 큰 native 메모리가 호출 될 때 발생된다.

 

일단 jvm 메모리 구조를 보자.(출처 http://www.nextree.co.kr/p3878/)

Native Heap Area OOME는 위에 설명처럼 Native Object들이 거주하는 공간에 더 이상 가용할 수 있는 메모리가 없기 때문에 발생하는 에러이다. 또한 이번 에러 로그에는 특정 소스의 몇 번째 라인에서 발생하는지 출력이 되었다.

해당 라인은 클라이언트에서 특정 url이 요청 되면 사진파일을 ServletOutputStream 객체에 flush()메소드를 호출하는 부분이었는데, 소스를 보니 flush()를 여러번 호출하도록 되어있었다.

여러 구글링을 해보니 OutputStream의 close()메소드가 마지막에 모두 flush를 한다고 명시되어있으며 flush()를 많이 사용할 경우 문제가 발생할 수 있다고 설명이 되어있었다.

flush()메소드를 모두 제거한 후 jmeter로 해당 url을 사이트 환경과 비슷하게 맞춘 후 테스트한 결과 oome는 발생하지 않았다.

추후 사이트 적용하여 모니터링 할 예정이다.

tomcat에 일부 로그들이 계속 쌓이게 되어 일정 주기를 설정하여 자동으로 삭제하도록 하는 프로세스를 개발하였다.

catalina.out 로그는 리눅스에서 logrotate.d에 등록하여 쉽게 관리할 수 있으나, localhost.*.log, localhost_access_log.*.txt, manager ... , 특정 was 로그 등 log4j나 logback에서 maxhistory로 최대 파일갯수를 설정하였는데 삭제가 안되는 이슈가 있었기 때문에 이러한 프로세스를 개발하게 되었다.

 

1. 패키지 구성

패키지는 main 메소드가 있는 LogRotate.java 와 FilenameFilter interface를 상속받는 MyFilenameFilter.java로 구성하였다.

 

먼저 MyFilenameFilter.java의 소스를 확인하자.

<MyFilenameFilter.java 소스>

package com.logrotate;

import java.io.File;
import java.io.FilenameFilter;

public class MyFilenameFilter implements FilenameFilter{

	private String file_name;
	
	public MyFilenameFilter(String file_name) {
		this.file_name=file_name;
	}
	
	@Override
	public boolean accept(File dir, String name) {
		// TODO Auto-generated method stub
		if(name.contains("ucex")) {
			return name.split("_")[0].equals(file_name);
		}else {
			return name.split("\\.")[0].equals(file_name) && !name.contains("out");
		}
	}

}

FilenameFilter interface를 상속받은 class에서 마지막 남은 로그의 갯수를 확인하기 위해 override한 accept 메소드를 위와 같이 구현하였다.

ucex는 특정 was 프로젝트의 이름으로 해당 프로젝트에서 ucex_2019-xx-xx_x.log 형태로 로그를 생성하여 split("_")을 통해 ucex가 포함된 로그가 filter되도록 정의하였다.

else문에서는 localhost.2019-xx-xx.log, localhost_access_log.2019-xx-xx.txt, 등 해당 로그들에 대한 filter를 정의해 주었으며, out이 포함된 로그는 제외하도록 하였다.(catalina.out로그는 리눅스의 logrotate.d에서 관리)

<LogRotate.java 소스>

package com.logrotate;

import java.io.File;
import java.io.FilenameFilter;
import java.util.Arrays;
import java.util.Date;

public class LogRotate{
	
	public String[] filenameFilter(File file) {

		String file_name="";
		if(file.getName().contains("ucex")) {
			file_name=file.getName().split("_")[0];
		}else {
			file_name=file.getName().split("\\.")[0];
		}
		
		return new File(file.getParent()).list(new MyFilenameFilter(file_name));
	}
	
	//first arg : 파일 경로, second arg : 삭제 기준일
	public static void main(String [] args) {
		LogRotate dt = new LogRotate();
		long todayMil = new Date().getTime();
		//1일을  milliseconds로 환산
		long oneDayMil = 24*60*60*1000;
		File path = null;
		int delete_standard_day = Integer.parseInt(args[args.length-1]);
		System.out.println("File Delete Standard Day : "+delete_standard_day);
		for(int j=0;j<args.length-1;j++) {
			String file_path = args[j];
			
			System.out.println("File Delete Dir Path : "+file_path);
			
			path = new File(file_path);
			//catalina.out 로그는 제외
			File[] file_list = path.listFiles(new FilenameFilter() {
				
				@Override
				public boolean accept(File dir, String name) {
					// TODO Auto-generated method stub
					return !name.contains("out");
				}
			});
			Arrays.sort(file_list);
			for(int i=0;i<file_list.length;i++) {
				//파일의 마지막 수정 시간 가져오기
				long fileDayMil = todayMil - file_list[i].lastModified();
				int fileDay = (int)(fileDayMil/oneDayMil);
				int len = dt.filenameFilter(file_list[i]).length;
				if(len>1 && fileDay>delete_standard_day) {
					file_list[i].delete();
					System.out.println("Delete to File Name : "+file_list[i].getName());
				}					
			}
		}	
		System.exit(0);
	}
}

LogRotate.java에서는 main()과 filenameFilter()를 정의하였다.

main()는 파일경로와 삭제 기준일을 arguments값으로 받으며, 마지막 arguments값은 무조건 삭제 기준일이여야 한다.

Date()를 이용하여 현재 시간값을 구하고 각 파일들의 시간값들과 비교하여 main()에 arguments값으로 넘어온 삭제 기준일과 비교하여 삭제하도록 구현하였다.

또한 filenameFilter()에서 해당 MyFilenameFilter생성자를 사용하여 각 파일에 대한 갯수를 가져올 수 있도록 하여 각 로그파일들이 1개씩 남아있을 경우 지우지 않도록 구현하였다.

파일 삭제가 종료될 시에 해당 프로세스를 자동으로 종료하도록 System.exit(0)를 넣어주었다.

(jar파일로 실행할 경우 종료해주지 않으면 프로세스가 계속 살아있어 추후에 크론이 주기적으로 실행시킬 경우 해당 프로세스가 계속 쌓이게됨)

 

<logrotate_start.sh 소스>

#!/bin/sh

logrotate_path=/home/cmuc/logrotation
tomcat_log_path=/home/cmuc/tomcat/apache-tomcat-7.0.47/logs
ucex_log_path=/home/cmuc/ucex/logs
logrotate_log_path=/home/cmuc/logrotation
delete_day=30

sleep 1

#LAST argumetns is delete_day
java -jar ${logrotate_path}/LogRotate.jar ${tomcat_log_path} ${ucex_log_path} ${delete_day} > ${logrotate_log_path}/logrotate.log

java소스들을 jar파일로 컴파일한 후 위의 쉘스크립트를 리눅스의 crontab에 등록하여 매일 새벽 3시에 동작하도록 하였다.

<crontab 등록 예시> 0 3 * * * cmuc /home/cmuc/logrotation/logrotate_start.sh

모든 경로는 절대 경로로 지정해야 crontab에서 정상적으로 동작한다. 위의 경로들은 프로젝트에 맞게 변경해주면 되겠다.

 

ps. 티스토리 패치 후에 소스코드 안에 <code></code>값이 계속 들어가 사라지지 않네요..

'java' 카테고리의 다른 글

OutOfMemory(OOME) 분석 및 java tomcat 튜닝  (0) 2019.04.05

+ Recent posts