TIL

Chapter 8. GC 로깅, 모니터링, 튜닝, 툴

8.1 GC 로깅 개요

• GC 로그는 시스템이 내려간 원인을 찾는 ‘콜드 케이스’ 분석을 할 때 미우 유용하다.
  • 로그를 분석하기 때문에 애플리케이션 프로세스가 살아있지 않아도 된다.
• 모든 중요한 애플리케이션에는 다음 두 가지를 설정해야 한다.
  • GC 로그를 생성한다.
  • 애플리케이션 출력과는 별도로 특정 파일에 GC 로그를 보관한다.
• GC 로깅은 오버헤드가 거의 없기에 주유 JVM 프로세스는 항상 로깅을 켜놓아야 한다.

8.1.1 GC 로깅 켜기

• 다음 스위치를 추가한다.

-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintTenuringDistribution
-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

| 플래그 | 작용 | | — | — | | -X:loggc:gc.log | GC 이벤트에 로깅할 파일을 지정 | | -XX:+PrintGCDetails | GC 이벤트 세부 정보를 로깅 | | -XX:+PrintTenuringDistribution | 툴링에 필요한, 부가적인 GC 이벤트 세부 정보 추가 | | -XX:+PrintGCTimeStamps | GC 이벤트 발생 시간을 (VM 시작 이후 경과한 시간을 초 단위로) 출력 | | -XX:+PrintGCDateStamps | GC 이벤트 발생 시간을 (벽시계 시간 기준) 출력 |

• 주의할 점
  • 기존 플래그 verbose:gc는 지우고 대신 PrintGCDetails를 사용
  • PrintTenuringDistribution은 독특한 플래그로 이 플래그가 제공하는 정보를 사람이 이용하기 어렵다.
    • 중요한 메모리압(memory pressure) 효과, 조기 승격 등의 이벤트 계산 시 필요한 기초 데이터를 제공
  • PrintBCDateStamps와 PrintGCTimeStamps는 둘 다 필요
    • 전자는 GC 이벤트와 애플리케이션 이벤트를 연관 짓는 용도
    • 후자는 GC와 다른 내부 JVM 이벤트를 연관 짓는 용도

8.1.2 GC 로그 vs JMX

• 자바 관리 확장(Java Management eXtensions) 인터페이스를 통해 JVM 데이터를 수집한다.
• JMX는 GC에 영향을 준다.
  • GC 로그 데이터는 GC 이벤트가 발생해서 쌓이지만 JMX는 데이터를 샘플링하여 얻는다.
  • GC 로그 데이터는 캡쳐 영향도가 거의 없지만 JMX는 프록시 및 원격 메서드 호출 과정에서도 암묵적인 비용이 든다.
  • GC 로그 데이터에는 자바 메모리 관리에 연관된 성능 데이터가 50가지 이상 있지만 JMX는 10가지도 안 된다.
• JMX는 성능 데이터 원천으로서 스트리밍된 데이터를 즉시 제공할 수 있다.

기본적인 힙 상태를 파악하는 용도로는 JMX가 제격이지만 깊이 있는 진단에서는 부족하다.

• JMX로 가져온 빈은 표준 빈이고 쉽게 엑세스 가능하다.
  • MBean이라고 부르는데 각종 디바이스, 애플리케이션을 비롯한 관리되어야 할 리소스를 빈으로 나타낸 것

8.1.3 JMX의 단점

• JMX를 이용하면 대부분 런타임을 샘플링하여 현재 상태를 업데이트한다.
  • 클라이언트는 런타임에 있는 JMX 빈을 풀링한다.
• 문제는 가비지 수집
  • GC 실행 시점을 알 수 없어 수집 전후 메모리 상태 역시 알 수가 없다.
  • 정확한 분석에선 GC 전후 힙 상태 정보가 대단히 중요하다.
  • 즉 GC 데이터를 깊이 있고 정확하게 분석할 수 없다.
• JMX로 얻은 데이터로는 장기적 추이를 파악하는 정도로만 쓸 수 밖에 없다.
• 메모리압(할당률)을 분석하는 활동이 매우 중요한데 JMX는 이를 할 수 없다.
• JMXConnector 명세를 구현한 코드는 내부적으로 RMI에 의존하므로 RMI 기반 통신 채널의 고질적 문제점에 취약하다.
  • 방화벽에 포트를 열어야 하므로 부차 소켓 접속이 맺어질 수 있다.
  • 프록시 객체를 이용해 remove() 메서드 호출을 대행
  • 자바 종료화(finallization)에 의존
  • RMI를 사용하면 기본 1시간에 한 번씩 풀 GC가 발생

8.1.4 GC 로그 데이터의 장점

• GC 튜닝의 복잡함을 감안하더라도 런타임에 발생한 일을 파악하는 데 GC 로그는 아주 유용하다.

GC 로그는 핫스팟 JVM 내부에서 논블로킹 쓰기 매커니즘을 이용하여 남긴다. 애플리케이션 성능에 미치는 영향은 거의 0이므로 운영계는 무조건 켜두어야 한다.

• GC 로그에 쌓인 기초 데이터는 특정 GC 이벤트와 연관 지을 수 있다.
• GC 로그를 통해 모든 의미 있는 분석 작업을 수행할 수 있다.

8.2 로그 파싱 툴

• GC 로그 메시지는 정해진 언어나 VM 명세 표준 포맷이 따로 없다.
  • 핫스팟 GC 개발팀 마음이라 릴리즈 간 포맷이 조금씩 다르다.
• 단순한 로그 포맷 파싱은 어렵지 않지만 GC 로그 플래그가 하나둘 추가되면 로그도 엄청 복잡해진다.
• GC 설정을 변경해 로그 출력 포맷이 달라지면 수동 GC 로그 파서를 쓰는 시스템에선 로깅이 끊어질 수 있다.

스스로 GC 로그를 파싱하려고 하지 말고 반드시 툴을 사용할 것

8.2.1 센섬

• jClarity사가 제작한 상용 메모리 분석기
• 센섬은 최고의 GC 로그 파싱, 정보 추출, 자동 분석 기능을 제공하는 것이 목표이다.
• 센섬 SaaS 모니터링 서비스를 이용하면 전체 클러스터 상태를 한눈에 볼 수 있다.
• OpenJDK 소스에 체크인된 코드베이스 중 로깅 관련 소스 코드를 낱낱이 분석해서 변경된 로그파일 포맷을 철저히 반영한다.
• 센섬 최신 버전이 지원하는 자동 분석 기능
  • 정확한 할당률
  • 조기 승격
  • 공격적인 할당
  • 유저 이탈
  • 메모리 누수 감지
  • 힙 크기 조정 및 용량 계획
  • VM에 대한 OS 간섭
  • 크기를 잘못 잡은 메모리 풀
• 자세한 정보는 https://www.jclarity.com 참고

8.2.2 GCViewer

• GC 로그 파싱 및 그래프 출력 등 기본 기능을 갖춘 데스크톱 툴
• 오픈소스인 점이 장점이지만 상용 툴에 비해 빈약하긴하다.
• https://github.com/chewiebug/GCViewer를 내려받아 컴파일/빌드 후 실행 가능한 JAR 파일로 패키징하면 된다.
• GC 로그파일은 GCViewer 메인 UI에서 열어볼 수 있다.
• 분석 기능은 없고 특정 GC 핫스팟 로그 포맷만 파싱할 수 있다.

8.3 GC 기본 튜닝

• GC 튜닝 역시 다른 튜닝 기법처럼 전체 진단 과정의 일부여야 한다.
• GC 튜닝 시 기억할 점
  1. GC가 성능 문제를 일으키는 원인이라고 확인하거나 그렇지 않다고 배제하는 행위는 저렴하다.
  2. UAT에서 GC 플래그를 켜는 것도 저렴한 행위
  3. 메모리 프로파일러, 실행 프로파일러를 설정하는 작업은 결코 저렴하지 않다.
• 엔지니어는 튜닝 시 다음 네 가지 주요 인자를 면밀히 관찰/측정해야 한다.
  • 할당, 중단 민감도, 처리율 추이, 객체 수명
  • 가장 중요한 요인은 ‘할당’

• 힙 크기를 조정하는 기본 플래그

  플래그	작용
  -Xms	힙 메모리의 최소 크기를 설정
  -Xmx	힙 메모리의 최대 크기를 설정
  -XX:MaxPermSize=	펌젠 메모리의 최대 크기를 설정 (자바 7 이전)
  -XX:MaxMetaspaceSize=	메타스페이스 메모리 최대 크기를 설정 (자바 8 이후)

• 튜닝 시 GC 플래그는 다음과 같이 추가한다.
  • 한 번에 한 플래그씩 추가한다.
  • 각 플래그가 무슨 작용을 하는지 숙지해야 한다.
  • 부수 효과를 일으키는 플래그 조합도 있음을 명심한다.
• 현재 이벤트 발생 중이라면 성능 문제 원인이 GC인지 아닌지 판단하는건 어렵지 않다.
  • vmstat 같은 툴로 고수준 머신 지표를 체크하고 다음을 확인한다.
  • CPU 사용률이 100%에 가까운가?
  • 대부분의 시간(90%이상)이 유저 공간에서 소비되는가?
  • GC 로그가 쌓이고 있다면 현재 GC가 실행 중이라는 증거
• 지난 이벤트를 조사하려면 모니터링 이력 데이터가 쌓여 있어야 한다.
  • CPU 사용률, 타임스탬프가 찍힌 GC 로그 등
• 세 가지 조건이 다 맞는다면 GC 성능 이슈를 일으키고 있을 가능성이 크고 튜닝이 필요하다.

8.3.1 할당이란?

• 할당률 분석은 튜닝 방법뿐 아니라 실제로 GC 튜닝 시 성능이 개선될지 여부를 판단하는 데 꼭 필요한 과정이다.
• 영 GC 이벤트 데이터로 할당된 데이터양, 단위 수집 시간을 계산할 수 있다.
  • 일정 시간 동안의 평균 할당률도 산출할 수 있다.

할당률을 수작업으로 계산하지 말고 툴을 써서 계산할 것

• 할당률 수치가 1GB/s 이상으로 일정 시간 지속한다면 십중팔구 GC 튜닝만으로는 해결할 수 없는 성능 문제다.
  • 이 경우 애플리케이션 핵심부의 할당 로직을 제거하는 리팩터링을 수행해야 한다.
• 초기 할당 전략은 다음 네 가지 단순 영역에 집중하는 것이 좋다.
  • 굳이 없어도 그만인 사소한 객체 할당 (로그 디버깅 메시지)
  • 박싱 비용
  • 도메인 객체
  • 엄청 많은 논JDK 프레임워크 객체
• 드물지만 도메인 객체가 메모리를 많이 차지하는 일도 있는데 주로 다음 타입 문제다.
  • char[]: 스트링을 구성하는 문자
  • byte[]: 바이너리 데이터
  • double[]: 계산 데이터
  • 맵 엔트리
  • Object[]
  • 내부 자료 구조 (ex: methodOop, klassOop)
• 도메인 객체가 위의 타입 문제로 너무 뚱뚱하면 조기 승격 문제를 겪게 된다.
  • 스레드 당 TLAB 크기가 동적 조정되는데 너무 큰 객체로 인해 TLAB 할당이 어려울 수 있다.
  • 그러면 에덴에 직접 객체 할당을 시도한다.
  • 이것도 실패하면 영 GC를 수행한다.
  • 그래도 공간이 부족하면 테뉴어드 영역에 직접 할당한다.
• 핫스팟은 TLAB 및 큰 객체의 조기 승격에 관한 튜닝 플래그를 제공한다.
  • -XX:PretenureSizeThreashold=<n>
  • -XX:MinTLABSize=<n>
• 할당률은 테뉴어드로 승격되는 객체 수에 영향을 끼친다.
  • 할당률이 높을수록 영 GC 주기가 짧아지고 단명 객체가 테뉴어드로 잘못 승격될 가능성이 크다.
• 조기 승격 문제는 다음 스위치가 유용하다.
  • -XX:MaxTenuringThreshold=<n>
  • 테뉴어드로의 승격 전까지 객체가 겪어야 할 GC 횟수를 설정 (디폴트: 4, 1 ~ 15 설정 가능)
  • 한계치가 높을수록 진짜 장수한 객체를 더 많이 복사하고, 한계치가 너무 낮으면 단명 객체가 승격되어 메모리압을 가중시킨다.

8.3.2 중단 시간이란?

• 대부분의 애플리케이션에서 100밀리초 정도의 중단 시간은 무시할 만하다.
  • 웹 애플리케이션 등에서 100 ~ 200 밀리초 정도의 중단은 눈치채기도 어렵다.
• 중단 시간 튜닝 시 유용한 휴리스틱
  1. 1초: 1초 이상 걸려도 괜찮다.
  2. 1초 ~ 100밀리초: 100밀리초 이상 1초 이하 정도는 괜찮다.
  3. < 100 밀리초: 100밀리초까지는 괜찮다.
     • 중간 민감도를 애플리케이션 힙 크기와 대략 연관 지어보면 어떤 수집기가 적합한지 가늠할 수 있다.

동시 수집기를 사용할 경우 중단 시간 튜닝보단 할당률부터 줄여야 한다. 할당률이 낮아지면 동시 수집기에 가해지는 메모리압도 낮아지므로 수집 사이클이 스레드 할당 속도를 따라가기 쉬워진다. 또 CMF 이벤트 발생 확률이 감소한다.

8.3.3 수집기 스레드와 GC 루트

• GC 루트 탐색 시간은 다음 요인에 영향을 받는다.
  • 애플리케이션 스레드 개수
  • 코드 캐시에 쌓인 컴파일드 코드량
  • 힙 크기
• 런타임 조건 및 적용 가능한 병렬화 정도에 따라서도 달라진다.
  • ex) 마킹 단계에서 엄청 큰 Object[]를 발견했다고 하면 이 단일 스레드의 탐색 시간이 전체 마킹 시간을 결정짓게 된다.
  • 객체 그래프가 복잡해질수록 이런 현상은 더욱 심해진다.
• 애플리케이션 스레드가 너무 많아도 GC 시간에 영향을 끼친다.
  • 스택 프레임을 더 많이 탐색해야 한다.
  • 세이프포인트에 도달하는 시간도 길어진다.
• JNI 프레임과 JIT 컴파일드 코드용 캐시 등 다른 GC 루트 원천들도 있다.

8.4 Parallel GC 튜닝

• Parallel GC는 가장 단순한 수집기라 튜닝이 쉽다.
• 병렬 수집기의 목표와 트레이드 오프
  • 풀 STW
  • GC 처리율이 높고 계산 비용이 싸다.
  • 부분 수집이 일어날 가능성은 없다.
  • 중단 시간은 힙 크기에 비례하여 늘어난다.
• 힙이 4GB 이하로 작을 경우 Parallel GC는 아주 효과적인 선택
• 과거에는 다양한 메모리 풀 상대적 크기를 조정하기도 했지만 명시적으로 크기를 설정하는 일은 삼가는 게 좋다.
  • 최신 애플리케이션은 사람보다 프로그램이 크기를 알아서 잘 결정하기 때문
  • ex) 영 세대/전체 힙 비율, 서바이버 공간/영 세대 비율, 최소 영 세대 크기 등

8.5 CMS 튜닝

• CMS로 최상의 성능을 얻는 과정엔 여러 복잡성과 트레이드 오프가 있다.
• CMS는 정말로 STW 중단 시간을 단축시켜야 하는 유스케이스에 한해 어쩔 수 없을 때만 사용해야 한다.
  • 그렇지 않으면 이렇다 할 성능 향상도 못 본 채 튜닝하기 힘든 수집기를 쓰게 되는 것
  • ‘중단 시간은 나쁘다, 고로 동시 마킹 수집기가 더 좋다’는 선입견
• CMS 플래그 가짓수는 방대해서 안티패턴의 늪에 빠질 우려가 있다.
  • 플래그가 java 8u131 기준 100여개

백투백

• 그럼에도 CMS 수집기를 튜닝하고자 한다면 CMF 발생 직전 수집기 상태를 살펴봐야 한다.
• CMS가 끝나자마자 곧바로 CMS가 시작되는 백투백 수집 현상은 CMF가 일어날 신호
  • 백투백 현상이 일어나면 애플리케이션 실행 처리율은 50%나 떨어진다. (GC에 코어 절반이 쓰이기 때문)
• 백투백이 일어나도 괜찮다면 코어 수를 늘리는 해결 방안을 모색해야 한다.
• CMS 수집 중 GC에 할당되는 코어 수를 줄이는 방법도 있다.
  • -XX:ConGCThreads=<n>
  • 그만큼 GC 수행 CPU 시간이 줄어든다.
  • 부하 급증 시 애플리케이션 회복력이 떨어진다.
  • 결국 CMF에 더 취약해진다.

CMS에서 STW

• CMS에서 STW은 두 단계에서 발생한다.
  • 초기 마킹 (GC 루트가 직접 가리키는 내부 노드 마킹)
  • 재마킹 (카드 테이블을 이용해 조정이 필요한 객체 식별)
• 따라서 모든 애플리케이션 스레드는 CMS마다 2회 멈춘다.
  • 세이프포인트에 예민한 저지연 애플리케이션에선 중요한 영향을 미칠 수 있다.
• 다음 두 플래그를 적용하면 도움이 된다.
  • -XX:CMSInitiatingOccupancyFraction=<n>
    • CMS가 실행되면 영 수집을 통해 올드 영역으로 승격되는 객체들을 수용할 여유 공간이 필요
    • 여유 공간은 동적으로 조정되지만 첫 CMS를 가동시킬 추정치를 미리 정해 놓는 것
    • 기본적으로 최초 CMS 풀 GC는 힙이 75% 찼을 때 시작된다.
  • -XX:+UseCMSInitiatingOccpancyOnly
    • 초기 점유 공간을 동적 크기 조정하는 기능이 꺼진다.
    • 이 플래그는 함부로 켜면 안되는데 실제로 여유 공간을 줄일 일은 거의 없다. (매개변수 값을 75 이상으로)
  • 할당률이 심하게 튄다면 여유 공간을 늘리고(매개변수 값 줄이고) 능동적 크기 조정 기능을 끄는 전략을 구사할 수 있다.
    • CMS GC를 자주 일으키는 대가를 치르더라도 CMF를 줄이자는 의도

8.5.1 단편화로 인한 CMF

• 튜닝 분석에 필요한 데이터가 GC 로그에만 존재하는 다른 사례
• CMS가 관리하는 프리 리스트 때문에 CMF가 발생할 수 있다.
• 프리 리스트 통계치를 바탕으로 힙 단편화로 인한 CMF 발생 가능성을 알 수는 없을까?

• -XX:PrintFLSStatistics=1 스위치를 추가하면 추가 정보가 표시된다.

    Total Free Space: 40115394
    (총 프리 공간)
      
    Max Chunk Size: 38808526
    (최대 청크 크기)
      
    Number of Blocks: 1360
    (블록 개수)
      
    Av. Block Size: 29496
    (평균 블록 크기)
      
    Tree Height: 22
    (트리 높이
  

• 평균 블록 크기와 최대 청크 크기를 보니 청크 크기 분포를 대략 짐작할 수 있다.
  • 큰 객체를 테뉴어드로 옮기려고 하는데 그만한 크기 청크가 바닥난 경우 CMF로 이어지게 된다.

8.6 G1 튜닝

• G1 튜닝의 최종 목표
  • 엔드 유저가 최대 힙 크기와 최대 GC 중단 시간을 간단히 설정하면 나머지는 수집기가 알아서 처리하는 것
  • 현실은 조금 다르다.
• G1을 튜닝하려면 다음 스위치를 반드시 지정해야 한다.
  • -XX:+UnlockExperimentalVMOptions
  • 특히 -XX:G1NewSizePercent=<n>나 -XX:G1MaxNewSizePercent=<n>을 사용할 경우 꼭 필요하다.
• G1 튜닝의 가장 큰 문제는 처음 등장한 이후로 내부적으로 상당히 많은 변화를 겪었다는 것이다.
• G1은 자바 9부터 디폴트 수집기이기 때문에 어쩔 수 없이 G1 튜닝 문제도 함께 다루어야 한다.
• CMS와 달리 G1 수집기는 할당률에 뒤쳐지지 않는 한 조금씩 메모리를 압착하기에 CMF가 일어날 가능성은 전혀 없다.
• 할당률이 계속 높아져서 단명 객체가 생성되고 있다면 다음 튜닝을 고려해봄 직하다.
  • 영 세대를 크게 설정
  • 테뉴어드 한계치를 최대 15 정도로 늘려 잡는다.
  • 애플리케이션에서 수용 가능한 최장 중단 시간 목표를 정한다.

    8.7 jHiccup

• JVM이 연속적으로 실행되지 못한 지점(히컵, hiccup)을 보여주는 계측 도구
• 히컵을 일으키는 가장 흔한 원인은 GC STW 중단
• jHiccup은 자바 명령줄에서 -javaagent:jHiccup.jar를 지정해 자바 에이전트로 사용한다.
  • Attach API로도 사용할 수 있다.
  • jHiccup -p <프로세스 ID>
• 기술적 세부 내용이 궁금하면 닛산 와카트가 게시한 블로그를 참고