본문 바로가기
Java/JVM

[JVM] GC 벤치마크 분석 포인트

RoyOps 2022. 1. 23. 21:01

[JVM] GC 벤치마크 개요 (링크)에서 분석에 필요한 Dump 파일과 Log 파일을 추출하고 툴을 사용하여 보기좋게 결과를 만드는 방법까지 진행하였다. 이번 장에서는 추출한 결과 파일을 분석하는 방법에 대해서 알아본다.

  1. Heap Dump 분석
    • Swallow Heap: 한 객체만이 점유한 Heap의 크기
    • Retained Heap: 한 객체가 제거될 때 함께 제거될 수 있는 객체들이 점유한 Heap의 크기. 자신이 GC 될 때 함께 GC 될 수 있는 참조하고 있는 객체의 메모리의 크기.
    • Unreachable Object: Heap 영역에 값이 할당되어 있지만 이를 참조하는 변수가 Stack 영역에 없는 Object
    • Dominator Tree: 객체간 참조관계를 나타내는 Tree, Keep Alive Tree라고도 부른다.
    • GC Root: Heap 외부에서 Heap을 참조할 수 있는 객체나 변수. Mark & Sweep 과정에서 Mark 작업이 시작될 때 시작. Dominator Tree의 최상단 노드.
    • 그림1 -
    • GC Root 종류: Java 스택 영역의 참조, JNI Native 스택 영역의 참조, Method Area의 정적 변수 참조
    • 그림 2-
    • Incoming 참조: 선택한 객체의 부모객체로 선택한 객체를 참조하는 객체
    • Outgoing 참조: 선택한 객체의 자식객체로 선택한 객체가 참하는 객체
    • Immediate Dominator: 선택한 객체를 GC시키는 부모객체
    1-1. MAT의 Leak Suspects 사용The thread org.apache.tomcat.util.threads.TaskThread @ 0x70be28e28
    http-nio-8080-exec-2 keeps local variables with total size 1,068,539,808 (74.38%) bytes.
    The memory is accumulated in one instance of org.apache.tomcat.util.threads.TaskThread,
    loaded by org.springframework.boot.loader.LaunchedURLClassLoader @ 0x70a956630,
    which occupies 1,068,539,808 (74.38%) bytes.이번에는 Details를 눌러서 stacktrace와 메모리를 많이 사용하고 있는 부분을 확인해본다.
    아래 이미지에서 빨갛게 표시된 부분을 중점적으로 확인해본다.
    • 가장 하단부의 *.doQueryAndInitializeNonLazyCollections의 로컬변수인 StatefulPersistenceContext 객체가 104 byte의 shallow heap을 가지고 있으며 279 mb의 retained heap을 가지고 있다.
      • 이후 기록을 확인해보면 쿼리를 실행시키고 결과를 가져오는 것을 확인할 수 있다.
      • 다음으로 log4j를 통해 로그를 찍기위해서 *.logMessageSafety의 로컬변수인 SimpleMessage에서 373 mb의 retained heap을 가지고 있다.
      이번에는 가장 상단을 확인해본다.
    • *.Arrays.copyOf의 로컬 변수인 373 mb 크기의 byte array를 사용하는 것을 확인 가능하다.
      1-2. Histogram을 사용하는 방법
      • overview에서 histogram을 선택한다.
      • Memory를 많이 사용하는 Class(필자의 경우 byte[])를 우클릭하고 incoming-reference를 선택한다.
      1-3. Dominator Tree를 사용하는 방법
      • overview에서 Dominator Tree를 선택한다.
      • Shallow Heap or Retained Heap을 내림차순 정렬하여 메모리를 많이 쓰는 객체를 확인
    • Dominator-tree의 경우 해당 객체가 참조하고 있는 모든 객체가 표시된다.
      1-1단계와 1-2단계와 동일하게 TaskThread @ 0x70be28e28 에서 많은 양의 메모리를 사용하는 것을 확인 가능하다.
    • 지금까지의 stacktrace를 확인해보면서 hibernate를 통해서 DB에서 데이터를 가져왔고
      가져온 데이터를 log4j를 통해서 로그를 찍기위해 373 mb의 byte array를 사용하였다는 것을 확인하였다.
  2. - 메모리를 많이 사용한 Thread의 이름: http-nio-8080-exec-2 - 메모리를 많이 사용한 인스턴스: org.apache.tomcat.util.threads.TaskThread @ 0x70be28e28 - 메모리를 많이 사용한 인스턴스를 생성한 클래스: org.springframework.boot.loader.URLClassLoader - GC 발생 시 http-nio-8080-exec-2 Thread에 의해 할당된 메모리의 양: 대략 1GB (GC된 메모리의 74.38%)
  4. 표현이 조금은 난해한데 간략하게 정리하면 아래와 같다.
  5. MAT에서 분석한 내용을 보면
  6. 분석을 진행하다보니 단순 stacktrace를 확인하는 것보다는 관련된 지역 변수까지 보여주는 See stacktrace with involved local variables(이하 Details)를 확인하는 것이 분석하기 편하였다. 아래의 예시는 Details를 통해서 이루어진다.
  7. [JVM] GC 벤치마크 개요 (링크)까지 진행하였다면 아래와 같은 이미지가 나올 것이다. Leak Suspects는 MAT가 추측한 Memory Leak 원인이다.
  8. 관련용어

지금까지 MAT의 Leak Suspects, Histogram, Dominator Tree를 사용하여 메모리를 많이 사용하는 객체를 파악하는 방법을 확인해보았다. 필자가 사용한 방법이외에도 MAT에서 많은 기능들을 지원하고 있으니 다른 방법도 알아보고 싶다면 MAT 공식문서 (링크를 확인해보도록 한다.

  1. Thread Dump 분석아래의 이미지는 Java Thread 상태 다이어그램이다.각 상태는 아래와 같은 의미를 가진다.
    • New: Thread가 생성되고 실행되지 않은 상태
    • Runnable: CPU를 점유하고 작업을 수행 중인 상태.
    • Blocked: Monitor를 획득하기 위해 다른 Thread가 Lock을 해제하기를 기다리는 상태
    • Waiting: wait(), join(), park() 메소드를 사용하여 대기하는 상태
    • Timed Waiting: Waiting과 동일하지만 최대 대기시간을 사용하여 Waiting 상태가 해제될 수 있는 상태
    • Terminated: Thread가 실행을 마친 상태
    • 필자의 Thread Dump를 분석하기 보다는 참고한 문서 (en) (링크), 참고한 문서 (kr) (링크)에서 제안하는 Thread Dump 분석할 때 주의깊게 봐야하는 포인트를 읽어보면 좋을듯 하다.
    • 필자가 이번에 분석을 진행하는 프로젝트는 규모가 작아서 Thread Dump에 분석할만한 데이터가 없었다.
      혹시라도 궁금한 사람을 위해 하단에 이미지 첨부한다.
  3. Java에서는 여러 Thread가 하나의 자원을 공유할 때 데이터의 정합성을 위하여 Monitor를 사용하여 한 번에 하나의 Thread만 자원에 접근할 수 있게한다.
    Java의 모든 객체는 하나의 Monitor를 가지고 있으며 Monitor는 하나의 Thread만 소유할 수 있다. 만약 어떠한 객체의 Monitor를 어떠한 Thread가 소유하고 있다면 다른 Thread들은 Monitor을 획득할 때까지 Wait Queue에서 대기해야한다.
    만약 Monitor를 선점한 Thread의 작업이 오래걸리게 된다면 이후의 Thread까지도 모든 작업이 느려지게 될 것이다.
    또한 Thread간의 DeadLock과 같은 현상을 파악하기 위해서는 Thread Dump를 파악해야하기 때문에 간략하게 Thread Dump를 확인해보도록 한다.
  1. GC Log관련용어
    • allocated: Java Application에 할당된 Heap Memory 사이즈 (Allocation이라는 용어는 Instance가 Eden영역에 할당될 때도 사용되므로 구분하여 사용하여야한다.)
    • Indicated the allocated size for each generation.
      This data point is gathered from the GC log, thus It may or may not Match with the size that is specified by the JVM system properties.
      Say you have configured total heap size as 2gb, whereas at runtime if JVM has allocated only 1gb, then in this report you are going to see the allocated size as 1gb only.
    • peak usage: 최대 힙메모리 사용량
    • Peak memory utilization of each generation.
      Typically it won't exceed the allocated size.
    • throughput: 어플리케이션 로직을 처리하는 데 소요된 시간과 GC 에 소요된 시간의 비율. 높을수록 좋음.
    • Percentage of time spent in processing real transaction vs time spent in GC activity. Higher percentage is a good indication that GC overhead is low.
      One should aim for high throughput.
      자세한 사항은 여기 (링크)에서 확인한다.
    3-1. GCEasy 분석 결과 페이지 상단의 한줄평(?)을 확인해본다.3-3. GC 수행 소요시간을 확인한다. 효율적인 GC가 이루어지는지 Throughput을 확인해본다.3-4. 대화형 그래프에서 여러 항목들을 확인해본다. 각 항목이 의미하는 것은 아래와 같다.
    • Heap after GC: GC 이후에 Heap Memory의 사이즈.
    • Heap beofre GC: GC 이전에 Heap Memory의 사이즈.
    • GC Duration: 전체 GC 이벤트 시간. Stop The World로 어플리케이션이 정지한 시간 + 어플리케이션이 정지하지 않고 GC가 이루어진 시간.
    • Pause GC Duration: GC로 인해 어플리케이션이 정지한 시간 (Stop The World).
    • Reclaimed Bytes: GC로 인해 회수된 메모리 용량.
    • Allocation & Promotion: Allocation은 어플리케이션에서 만든 객체의 양을 의미하며 Promotion은 Young 영역에서 Old 영역으로 Promotion되는 양을 의미한다.3-5. GC 단계별로 수행된 시간 통계를 확인해본다. (GC별로 단계가 다르므로 표시되는 항목은 변경될 수도 있다.)3-6. Pause, Concurrent 시간을 비교한 그래프를 확인한다.
      Pause는 어플리케이션이 중지되고 GC가 이루어진 시간이며, Concurrent는 어플리케이션이 중지되지 않고 GC가 수행된 시간이다.3-7. 생성된 객체의 정보를 확인한다. 각 항목이 의미하는 것은 아래와 같다.
    • Total created bytes: 어플리케이션이 실행되는 동안 생성된 객체의 총 용량. (적을수록 좋음)
    • Total promoted bytes: Young 영역에서 Old 영역으로 승격된 객체의 총 용량.
    • Avg creation rate: 시간당 객체 생산량. (낮을수록 좋음)
      Allocation 속도로 예상된다.
    • Objects creation rate by the application.
      When more objects are created, more GCs has to be run to reclaim those objects from memory.
      Single best tip for optimized performance is to keep the allocation rate as low as possible.
    • Avg promotion rate: 시간당 Young 영역에서 Old 영역으로 승격되는 객체의 양3-8. GC가 발생한 원인과 시간을 확인해본다. 각 항목이 의미하는 것은 아래와 같다.
    • Heap Dump Initiated GC: Heap Dump를 만들 때 발생하는 Full GC
    • G1 Evacuation Pause: Heap의 한 영역에서 다른 영역으로 객체를 Copy 할 때 발생하는 GC
    • G1 Humongous Allocation: Humongous (Region 사이즈의 50% 이상의 크기를 차지하는 객체) 객체를 처리하는 GC
    • GCLocker Initiated GC: JNI critical region에서 해제되었을 때 발생하는 GC. (C, C++과 같이 다른 네이티브 언어가 Java Heap의 배열 및 문자열에 대한 참조를 할 때 JNI critical region이 사용된다. 참조는 네이티브 코드가 release 함수를 호출할 때까지 유지되며 get 부터 release까지의 시간을 JNI critical 섹션이라고하며 이 시간동안에는 GC가 되지 않으며 release이후 참조가 해제되면 GC가 수행된다.)
    • Metadata GC Threshold: 구성된 메타스페이스 크기가 실제 요구사항보다 작은경우나 클래스 로더 누출이 있는 경우 발생하는 GC
    지금까지 GC 벤치마크를 진행할 때 주의깊게 봐야하는 분석 포인트에 대해서 알아보았다.
    다음 장부터 실제로 벤치마크를 진행하고 결과를 분석해본다.
  4. 3-2. JVM에 할당된 (allocated) 메모리와 최대 사용량 (peak usage)를 확인해본다.
  5. 이번 테스트 결과 정상적으로 GC가 작동하고 있음을 확인할 수 있다.
  6. GCEasy Report에 표시된 내용만 다루도록 한다.
    표시되지 않는 내용은 필자가 Log로 추출하지 않았거나 무료 버전에서는 사용하지 못하는 기능이다.

그림1 출처: https://velog.io/@mu1616/가비지-컬렉션-GC
그림2 출처: https://d2.naver.com/helloworld/329631

저작자표시

'Java > JVM' 카테고리의 다른 글

[JVM] GC 벤치마크 결과 데이터  (0) 2022.01.23
[JVM] GC 벤치마크 결과  (0) 2022.01.23
[JVM] GC 벤치마크 개요  (0) 2021.12.23
[JVM] GC 알고리즘 종류  (0) 2021.12.02
[JVM] Heap & GC  (0) 2021.12.02

'Java/JVM' Related Articles

티스토리툴바