[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 가 튀는 것은 당장의 문제가 되지는 않지만 문제가 누적되면 후에 장애로 발전할 수 있기 때문에 원인을 파악해보기로 결정.

 

분석

1. 어떤 요청에 의해서 Minor GC 가 튀는건지 확인.
   • 동일한 버전으로 서빙되는 서버중 특정 서버에서만 Minor GC 가 튀는것으로 보아 특정 요청에 의한 것으로 추측하여 어떤 요청인지 파악 시도
   • 해당 서버는 여러가지 타입의 엑셀 파일을 생성하는 서버이며 특정 타입의 엑셀 파일을 생성할때 Minor GC 가 발생하는것을 확인.
2. 분석을 위한 환경 구축 및 분석 방법 
   
   • 문제가 되는 엑셀 파일을 서버에서 생성할때 GC 가 발생하기 때문에 요청이 없는 테스트 서버에서 재현이 가능. 
   • 하지만 코드레벨에서 Minor GC 증가에 원인이 될만한 부분은 찾기 힘들어 HeapDump 를 분석해보기로 결정
   • Minor GC 가 발생하기 전 후의 Heapdump 를 분석하면 어떤 객체들이 Minor GC 를 유발하는지 확인할 수 있을거라 생각.
3. 어떤 함수가 실행될때 Minor GC 가 발생하는지 확인.
   • 엑셀을 만들기 위해 데이터를 불러오는 부분. 불러온 데이터로 엑셀을 만드는 부분 두 곳이 의심스러워서 로깅.
   • 메트릭에서 볼 수 있듯이 1분에 15~20번 발생하는 Minor GC 의 전 후에 힙덤프를 사람 손으로 뜨는건 불가능.
   • 의심되는 부분들에 Log 와 Thread.sleep() 함수를 이용하여 Minor GC 가 어떤 메서드가 실행될때 발생하는지 확인.

   • log.info("** method Called");
     Thread.sleep(50);

   • Thread.sleep() 값을 조절해서 Minor GC 가 발생하기 전 후에 Heapdump 를 뜨는게 가능.
4. 어떤 객체를 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 라는 필드명으로 사용하는 객체임을 확인

     

5. 코드 레벨에서 확인.
   • TextSaver 클래스에서 정말 사용되는지 그리고 어떤 경로로 호출되는지 breakpoint 잡아서 확인.

     

   • 엑셀을 만들때 TextSaver 클래스의 생성자가 호출되는것을 확인하였고 아래 로직에 의하여 4096 크기의 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];​

   • 하지만 다른 엑셀 종류의 엑셀을 만들때는 이러한 문제가 없어서 문제가 없는 엑셀 종류를 생성 요청해보니 위 break point 에 잡히지 않았다.
   • Call Stack 을 따라가보니 문제가 되는 엑셀 타입만 다른 Excel 생성 WorkBook 을 사용 하고 있었다.
     • 문제 Workbook : XSSFWorkBook
     • 정상 Workbook :  SXSSFWorkBook
   • Workbook 의 내부 로직 차이에 의한 것으로 보여 Workbook 을 교체하여 테스트해보니 Minor GC 발생 X
   • 그렇다면 정상 Workbook 에서는 char[] 사이즈가 어떻게 사용되고 있나 보니 아래와 같이 큰 사이즈를 기본으로 설정하지 않고 필요한 부분만 할당하여 사용하고 있다.

     

해결

 XSSFWorkBook 은 위 로직에서 보이는 것처럼 문자열에 대해서 메모리를 과하게 사용하고 있는것으로 보인다. 또한 엑셀 생성 로직은 플랫폼에서 제공하는 코드를 사용하여 공통적으로 SXSSFWorkBook 을 사용하여야 하는데 자체 작성한 코드로 XSSFWorkBook 을 사용하고 있으므로 공통 코드를 사용하도록 수정.

 XSSFWorkBook 은 문자열에 사용에 있어서 메모리 낭비가 심하므로 가능하면 사용하지 않는 방향으로 해야겠다.