on
[Java] Minor GC 증가 원인 파악기 (feat. Excel WorkBook)
[Java] Minor GC 증가 원인 파악기 (feat. Excel WorkBook)
minor gc spike 발생 Minor GC 관련 Alert 발생
현상
평소와 같은 요청량을 처리하는 서버에서 간혹 Minor GC 가 튀는 것을 Alert 과 Metric 으로 확인하였다. 요청량이 증가하지 않았는데 하나의 노드에서만 Minor GC 가 증가하였다. 각 매트릭의 의미는 아래와 같다.
Minor GC count : 1분동안 발생한 gc log 에 기록된 Minor GC 수의 합.
Minor GC Time : 1분동안 발생한 gc log 에 기록된 Minor GC 가 걸린 시간의 총 합.
Minor GC 가 튀는 것은 당장의 문제가 되지는 않지만 문제가 누적되면 후에 장애로 발전할 수 있기 때문에 원인을 파악해보기로 결정.
분석
어떤 요청에 의해서 Minor GC 가 튀는건지 확인. 동일한 버전으로 서빙되는 서버중 특정 서버에서만 Minor GC 가 튀는것으로 보아 특정 요청에 의한 것으로 추측하여 어떤 요청인지 파악 시도
해당 서버는 여러가지 타입의 엑셀 파일을 생성하는 서버이며 특정 타입의 엑셀 파일을 생성할때 Minor GC 가 발생하는것을 확인. 분석을 위한 환경 구축 및 분석 방법
문제가 되는 엑셀 파일을 서버에서 생성할때 GC 가 발생하기 때문에 요청이 없는 테스트 서버에서 재현이 가능.
하지만 코드레벨에서 Minor GC 증가에 원인이 될만한 부분은 찾기 힘들어 HeapDump 를 분석해보기로 결정
Minor GC 가 발생하기 전 후의 Heapdump 를 분석하면 어떤 객체들이 Minor GC 를 유발하는지 확인할 수 있을거라 생각. 어떤 함수가 실행될때 Minor GC 가 발생하는지 확인. 엑셀을 만들기 위해 데이터를 불러오는 부분. 불러온 데이터로 엑셀을 만드는 부분 두 곳이 의심스러워서 로깅.
메트릭에서 볼 수 있듯이 1분에 15~20번 발생하는 Minor GC 의 전 후에 힙덤프를 사람 손으로 뜨는건 불가능.
의심되는 부분들에 Log 와 Thread.sleep() 함수를 이용하여 Minor GC 가 어떤 메서드가 실행될때 발생하는지 확인.
log.info("** method Called"); Thread.sleep(50);
Thread.sleep() 값을 조절해서 Minor GC 가 발생하기 전 후에 Heapdump 를 뜨는게 가능. 어떤 객체를 Garbage Collection 하기 위해 Minor GC 가 발생하는지 확인을 위한 Heapdump 분석 Heapdump 결과 GC 가 발생하는 타이밍은 늦췄지만 언제 GC 가 발생하는지 알 수 없기 때문에 1분에 한번씩 Heapdump 를 뜨면서 GC 가 발생하기를 기다린다.
heapdump-0-4.hprof 이후에 GC 가 발생하고 heapdump-0-5.hprof 가 떠졌기 때문에 Heapdump 의 용량이 줄어든 것을 확인할 수 있다.
0-4 Heapdump 와 0-5 Heapdump 를 비교하면 어떤 객체들이 Minor GC 의 대상이 되었는지 확인 가능.
Memory Analyzer (MAT) 의 comapre heapdump 기능을 이용하여. GC 대상 객체들을 확인해야 하므로 Unreachable 객체도 파싱되도록 설정하여 힙덤프를 불러온다. ( https://woooongs.tistory.com/78 )
0-5 Heapdump 를 기준으로 0-4 와 비교한 heapdump 의 결과는 아래와 같다. char array, int array 가 대부분 GC 된 걸 확인할 수 있다. 비교 방법 ( https://woooongs.tistory.com/79 )
char[] 가 약 0.8G 의 공간을 차지하다가 GC 되었으므로 char[] 가 어떤 객체들을 포함하고 있는지 확인하면 Minor GC 원인을 알 수 있다.
0-4 Heapdump 에서 Unreachable 객체들 중 char[] 가 어떤 데이터를 가지고 있으며 어떤 클래스에 의해서 사용되는지 확인 ( https://woooongs.tistory.com/80?category=1035273 )
크기 순으로 char[] 를 정렬하였을때 상단의 에러 로깅을 위한 char[] 를 제외하고는 모두 동일한 크기 (4096)의 비슷한 형태의 데이터가 저장되어있다. 4096 사이즈를 가진 char array 가 100만개 이상 저장되어있음.
char[4096] 의 Value 를 복사해서 확인하니 아주 일부 데이터가 포함되어있고 나머지 영역은 모두 공백으로 설정되어있다.
char array 의 공간을 과하게 사용하는것이 Minor GC 의 원인 생각하여 해당 어레이를 만드는 클래스 파악. apache 라이브러리의 TextSaver 에서 _buf 라는 필드명으로 사용하는 객체임을 확인 코드 레벨에서 확인. TextSaver 클래스에서 정말 사용되는지 그리고 어떤 경로로 호출되는지 breakpoint 잡아서 확인.
엑셀을 만들때 TextSaver 클래스의 생성자가 호출되는것을 확인하였고 아래 로직에 의하여 4092 크기의 char[] 가 매번 생성되는 것을 확인 int newLen = this._buf == null ? 4096 : this._buf.length * 2; int used; for(used = this.getAvailable(); newLen - used < cch; newLen *= 2) { } char[] newBuf = new char[newLen];
from http://woooongs.tistory.com/81 by ccl(A) rewrite - 2021-11-12 11:00:25