콘텐츠로 이동

async-profiler를 활용한 애플리케이션 성능 튜닝

Info

Java 프로파일링은 JFR(Java Flight Recording) 방식 외에도 async-profiler를 통해 수행할 수 있습니다.

async-profiler 소개

async-profiler는 Safepoint bias problem이 없는 저오버헤드 Java 샘플링 프로파일러입니다. HotSpot의 특수 API를 사용하여 스택 정보 및 메모리 할당 정보를 수집하며, OpenJDK, Oracle JDK 및 기타 HotSpot 기반 Java 가상 머신에서 사용할 수 있습니다.

async-profiler는 다음과 같은 이벤트를 수집할 수 있습니다.

  • CPU cycles
  • 캐시 미스, 브랜치 미스, 페이지 폴트, 컨텍스트 스위치 등의 하드웨어 및 소프트웨어 성능 카운터
  • Java 힙 할당
  • Contented lock attempts(Java object monitors 및 ReentrantLocks 포함)

1. CPU 성능 분석

이 모드에서 프로파일러는 Java 메서드, 네이티브 호출, JVM 코드 및 커널 함수를 포함하는 스택 트레이스 샘플을 수집합니다.

일반적인 방법은 perf_events가 생성한 호출 스택을 수신하고 이를 AsyncGetCallTrace가 생성한 호출 스택과 매칭하여 Java 및 네이티브 코드에 대한 정확한 프로파일을 생성하는 것입니다.
또한, async-profiler는 AsyncGetCallTrace가 실패하는 특정 경우에 스택 트레이스를 복구하는 대체 방법을 제공합니다.

perf_events를 Java 에이전트와 함께 직접 사용하여 주소를 Java 메서드 이름으로 변환하는 방식과 비교할 때, 이 방법의 장점은 다음과 같습니다.

  • -XX:+PreserveFramePointer가 필요하지 않으므로 이전 Java 버전에서도 작동합니다. -XX:+PreserveFramePointer는 JDK 8u60 이상에서만 사용할 수 있습니다.
  • -XX:+PreserveFramePointer의 성능 오버헤드(드물게 최대 10%까지 발생 가능)가 없습니다.
  • Java 코드 주소를 메서드 이름에 매핑하기 위한 매핑 파일이 필요하지 않습니다.
  • 인터프리터 프레임에서도 작동합니다.
  • 사용자 공간 스크립트에서 추가 처리를 위해 perf.data 파일을 쓸 필요가 없습니다.

2. 메모리 할당 분석

CPU를 많이 사용하는 코드를 감지하는 대신, 프로파일러를 구성하여 가장 많은 힙 메모리를 할당하는 호출 사이트를 수집할 수 있습니다.

async-profiler는 성능에 큰 영향을 미칠 수 있는 바이트코드 계측이나 고가의 DTrace 프로브와 같은 침투적인 기술을 사용하지 않습니다. 또한 이스케이프 분석에 영향을 주거나 할당 제거와 같은 JIT 최적화를 방해하지 않습니다. 실제 힙 할당만 측정합니다.

이 프로파일러는 TLAB 기반 샘플링 기능을 제공합니다. HotSpot 특화 콜백에 의존하여 다음 두 가지 알림을 수신합니다.

  • 새로 생성된 TLAB(플레임 그래프의 하늘색 프레임) 내에서 객체가 할당될 때
  • TLAB 외부의 느린 경로(갈색 프레임)에서 객체가 할당될 때

즉, 모든 할당을 계산하는 것이 아니라 N kB당 한 번씩만 계산합니다. 여기서 N은 TLAB의 평균 크기입니다. 이로 인해 힙 샘플링은 매우 저렴해지고 프로덕션 환경에 적합합니다. 반면에 수집된 데이터는 불완전할 수 있지만, 실제로는 일반적으로 가장 높은 할당 소스를 반영합니다.

샘플링 간격은 --alloc 옵션을 통해 조정할 수 있습니다. 예를 들어 --alloc 500k는 평균 500KB의 공간이 할당된 후 한 번 샘플링합니다. 그러나 TLAB 크기보다 작은 간격은 적용되지 않습니다.
지원되는 최소 JDK 버전은 TLAB 콜백이 도입된 7u40입니다.

3. Wall-clock 프로파일링

-e wall 옵션은 async-profiler가 스레드 상태(실행 중, 슬립 중, 차단됨)에 관계없이 주어진 시간 간격마다 모든 스레드를 균등하게 샘플링하도록 합니다. 이는 애플리케이션 시작 시간을 분석할 때 특히 유용합니다.

Wall-clock 프로파일러는 스레드별 모드(-t)에서 가장 유용합니다.

예시: ./profiler.sh -e wall -t -i 5ms -f result.html 8983

4. Java 메서드 성능 분석

-e ClassName.methodName 옵션은 지정된 Java 메서드를 계측하여 스택 트레이스로 이 메서드의 모든 호출을 기록합니다.

  • 네이티브가 아닌 경우, 예시: -e java.util.Properties.getProperty는 getProperty 메서드가 호출된 모든 위치를 분석합니다.
  • 네이티브인 경우, 하드웨어 브레이크포인트 이벤트를 대신 사용하세요. 예시: -e Java_java_lang_Throwable_fillInStackTrace

참고: 런타임에 async-profiler를 연결하면, 네이티브가 아닌 Java 메서드의 첫 번째 계측으로 인해 컴파일된 모든 메서드의 역최적화가 발생할 수 있습니다. 이후 계측은 관련 코드만 새로 고칩니다.

async-profiler를 에이전트로 연결하면 대규모 CodeCache 새로 고침이 발생하지 않습니다.

다음은 분석에 유용할 수 있는 몇 가지 네이티브 메서드입니다.

  • G1CollectedHeap::humongous_obj_allocate - G1 GC의 _humongous allocation(거대 메모리 할당)을 추적합니다.
  • JVM_StartThread - 새 스레드 생성을 추적합니다.
  • Java_java_lang_ClassLoader_defineClass1 - 클래스 로딩을 추적합니다.

디렉토리 구조

image.png

시작 방법

async-profiler는 JVMTI(JVM Tool Interface)를 기반으로 개발된 에이전트로, 두 가지 시작 방법을 지원합니다.

    1. Java 프로세스와 함께 시작하여 공유 라이브러리를 자동으로 로드합니다.
    1. 프로그램 실행 중 attach API를 통해 동적으로 로드합니다.

1 시작 시 로드

참고

시작 시 로드는 애플리케이션 시작 시점에만 분석에 적합하며, 실행 중인 애플리케이션을 실시간으로 분석할 수는 없습니다.

JVM 시작 직후 일부 코드를 분석해야 하는 경우 profiler.sh 스크립트 대신 명령줄에 async-profiler를 에이전트로 추가할 수 있습니다. 예시:

$ java -agentpath:async-profiler-2.8.3/build/libasyncProfiler.so=start,event=alloc,file=profile.html -jar ...

image.png

에이전트 라이브러리는 JVMTI 매개변수 인터페이스를 통해 구성되며, 매개변수 문자열의 형식은 소스 코드에 설명되어 있습니다.

  • profiler.sh 스크립트는 실제로 명령줄 인수를 해당 형식으로 변환합니다.
    예를 들어 -e wall은 event=wall로, -f profile.html은 file=profile.html로 변환됩니다.
  • profiler.sh 스크립트가 직접 처리하는 일부 매개변수도 있습니다.
    예를 들어 -d 5는 3개의 작업을 포함합니다. start 명령으로 프로파일러 에이전트를 연결하고, 5초 동안 대기한 후 stop 명령으로 에이전트를 다시 연결합니다. image.png

2 실행 중 로드

더 자주 사용되는 경우는 애플리케이션이 실행 중일 때 분석이 필요한 경우입니다.

./profiler.sh -e alloc -d 10 -f out.html pid

image.png

당시의 메모리 사용 할당 상황을 확인할 수 있습니다. reader가 99.77%의 메모리를 할당했습니다.
현재 애플리케이션이 지원하는 이벤트 확인

./profiler.sh list jps

image.png

참고

html 형식은 단일 이벤트만 지원하며, jfr 형식은 여러 이벤트 출력을 지원합니다.

async-profiler와 Guance

Guance은 async-profiler와 긴밀하게 통합되어 있어 데이터를 DataKit으로 전송하고, Guance의 강력한 UI 및 분석 기능을 활용하여 사용자가 다양한 차원에서 분석을 수행할 수 있습니다.

관련 통합 문서를 참조하세요.

사례 분석

키-값 쌍 형식(key:value)으로 파일을 저장하고 이를 Map으로 파싱하는 대용량 파일을 빠르게 읽습니다.

1 대용량 파일 쓰기

import java.io.FileWriter;

public class MapGenerator {
    public static String fileName = "/opt/profiling/map-info.txt";
    public static void main(String[] args) {

        try (FileWriter writer = new FileWriter(fileName)) {
            writer.write("");//원본 파일 내용 지우기
            for (int i = 0; i < 16500000; i++) {
                writer.write("name"+i+":"+i+"\n");
            }
            writer.flush();
            System.out.println("write success!");
        } catch (Exception e) {
            e.printStackTrace();
        }

    }
}

2 대용량 파일 읽기

private static Map<String,Long> readMap(String fileName) throws IOException {
        Map<String,Long> map = new HashMap<>();
        try(BufferedReader br = new BufferedReader(new FileReader(fileName))) {
            for (String line ;(line = br.readLine())!=null;){
                String[] kv = line.split(":",2);
                String key = kv[0].trim();
                String value = kv[1].trim();
                map.put(key,Long.parseLong(value));
            }
        }
        return map;
    }

MapReader 실행, 전체 프로세스 소요 시간 15.5초.

[root@ip-172-31-19-50 profiling]# java MapReader
Profiling started
Read 16500000 elements in 15.531 seconds

MapReader 실행과 동시에 async-profiler를 실행하고 프로파일링 정보를 Guance 플랫폼으로 전송하여 분석합니다.

[root@ip-172-31-19-50 async-profiler-2.8.3-linux-x64]# DATAKIT_URL=http://localhost:9529 APP_ENV=test APP_VERSION=1.0.0 HOST_NAME=datakit PROFILING_EVENT=cpu,alloc,lock PROFILING_DURATION=10 PROCESS_ID=`ps -ef |grep java|grep springboot|grep -v grep|awk '{print $2}'` SERVICE_NAME=demo bash collect.sh
profiling process 16134

Profiling for 10 seconds
Done
generate profiling file successfully for MapReader, pid 16134
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  110k  100    64  100  110k     99   172k --:--:-- --:--:-- --:--:--  172k
Info: send profile file to datakit successfully
[root@ip-172-31-19-50 async-profiler-2.8.3-linux-x64]#

image.png

image.png

결과 
메모리 할당 상황을 확인하면 총 3.79GB의 메모리가 생성되었습니다.

private static Map<String,Long> readMap(String fileName) throws IOException {
        Map<String,Long> map = new HashMap<>();
        try(BufferedReader br = new BufferedReader(new FileReader(fileName))) {
            for (String line ;(line = br.readLine())!=null;){
                int sep = line.indexOf(":");
                String key = trim(line,0,sep);
                String value = trim(line,sep+1,line.length());
                map.put(key,Long.parseLong(value));
            }
        }
        return map;
    }

    private static String trim(String line,int from,int to){
        while (from<to && line.charAt(from) <= ' '){
            from ++;
        }
        while (to > from && line.charAt(to-1) <= ' '){
            to--;
        }
        return line.substring(from,to);
    }

MapReader2 실행, 전체 프로세스 소요 시간 11.257초.

[root@ip-172-31-19-50 profiling]# java MapReader2
Profiling started
Read 16500000 elements in 11.257 seconds
[root@ip-172-31-19-50 profiling]#

MapReader2 실행과 동시에 async-profiler를 실행하고 프로파일링 정보를 Guance 플랫폼으로 전송하여 분석합니다. 실행 명령은 방법 1과 동일합니다.

image.png

결과 
메모리 할당 상황을 확인하면 총 2.49GB의 메모리가 생성되었습니다. 방법 1보다 1.3GB의 메모리가 절약되었고, 소요 시간도 약 4초 감소했습니다.

private static Map<String,Long> readMap(String fileName) throws IOException {
        Map<String,Long> map = new HashMap<>(600000);
        try(BufferedReader br = new BufferedReader(new FileReader(fileName))) {
            for (String line ;(line = br.readLine())!=null;){
                int sep = line.indexOf(":");
                String key = trim(line,0,sep);
                String value = trim(line,sep+1,line.length());
                map.put(key,Long.parseLong(value));
            }
        }
        return map;
    }

    private static String trim(String line,int from,int to){
        while (from<to && line.charAt(from) <= ' '){
            from ++;
        }
        while (to > from && line.charAt(to-1) <= ' '){
            to--;
        }
        return line.substring(from,to);
    }

image.png

결과 
작업 단계는 방법 2와 동일합니다. MapReader3와 MapReader2의 차이점은 MapReader3가 Map 초기화 시 용량을 지정한다는 점입니다. 따라서 방법 3은 방법 2보다 0.3GB의 메모리를 절약하고, 방법 1보다는 1.6GB의 메모리를 절약합니다.

3 메트릭, 트레이스 연동 분석

위 데모 코드의 수명 주기가 매우 짧아 전방위적인 관측(JVM 관련 메트릭, 호스트 관련 메트릭 등)이 불가능하므로, 위 데모 코드를 Spring Boot 애플리케이션으로 마이그레이션하고 APM(ddtrace-agent)을 JVM 메트릭 및 async-profiler와 결합하여 메트릭(JVM/호스트), 트레이스(현재 추적 상태), 프로파일링(성능 분석)의 세 가지 차원에서 관측 가능성을 확보합니다. 해당 URL에 접근하여 async-profiler 분석 작업을 수행합니다.

  • 프로파일링 뷰

image.png

  • JVM 뷰

image.png

  • 트레이스 뷰

image.png

4 요약

image.png

TLAB 정보

TLAB의 전체 이름은 Thread Local Allocation Buffer(스레드 로컬 할당 버퍼)로, Java 메모리 할당의 개념입니다. 스레드가 객체를 생성할 때 메모리를 할당하는 스레드 전용 메모리 할당 영역입니다. 주로 멀티스레드 동시 실행 환경에서 스레드 간 메모리 할당 경합을 줄이기 위해 사용됩니다. 스레드가 메모리 영역을 할당받은 후, 현재 스레드가 메모리를 할당해야 하는 경우 우선적으로 이 영역에서 요청합니다. 따라서 이 영역은 현재 스레드에 전용이므로 할당 시 잠금과 같은 보호 작업이 필요하지 않습니다.

Note

대부분의 JVM 애플리케이션에서 대부분의 객체는 TLAB 내에서 할당됩니다. TLAB 외부 할당이 너무 많거나 TLAB 재할당이 너무 많은 경우, 코드를 확인하여 대용량 객체 또는 불규칙하게 확장되는 객체 할당이 있는지 검사하여 코드를 최적화해야 합니다.

Allocations in New TLAB Size

주로 jdk.ObjectAllocationInNewTLAB 이벤트를 수집하며, 이를 "TLAB 느린 할당"이라고 합니다.

Allocations Outside TLAB Size

주로 jdk.ObjectAllocationOutsideTLAB 이벤트를 수집하며, 이를 "TLAB 외부 할당"이라고 합니다.

프로파일링 도구 비교

image.png

참고 문서

<async-profiler>

<DataKit async-profiler 통합>

<async-profiler 데모 코드>

<async-profiler Spring Boot 데모 코드>

문서 평가

이 페이지가 도움이 되었나요?