Arthas JVM stack 툴(profiler)

프로젝트에서 부하 테스트를 진행 하던 중 일부 구간에서 오동작하는 이슈가 발생하였다.

특이한 것은 적은양의 트래픽으로는 별 다른 이슈는 없었으나 예상 최대 부하를 진행하였을 때 일부의 로직이 잘못 동작하는 것으로 보였다.(로직들이 비동기가 많기 때문에 더욱 문제를 찾기 어려웠음)

결국 최적화 팀을 불러 어느 구간이 문제였는지 찾을 수 있었는데 최적화 팀에서 사용하는 툴을 찾아보니 오픈소스 툴 이었다.

최적화 팀에서 사용한 방법을 해보고자 한다.

---

Arthas 사이트

https://arthas.aliyun.com/en/doc/

Arthas

 

Arthas는 알리바바 미들웨어 팀에서 만든 오픈소스의 JAVA 진단 툴이라고한다.

 

특징

• Class가 load 되어 있는지, 클레스가 어디로 부터 load 되었는지(jar 파일 충돌에 유용하다고 한다)
• 예상되로 동작하는지 Decompile
• 클레스로더의 통계(클래스 로더 수, 클래스 로더당 로드된 클래스 수, 클래스 로더 계층 구조, 가능한 클래스 로더 누수 등)
• 메소드 호출 세부정보(메소드의 변수, 반환값 등)
• 지정된 메소드의 stack 추적

등등

 

---

 

Arthas 테스트를 위한 설치

 

테스트 타겟이 될 JAVA 프로그램(math-game) arthas 다운로드

curl -O https://arthas.aliyun.com/math-game.jar
curl -O https://arthas.aliyun.com/arthas-boot.jar

 

math-game 실행해보기

(1초마다 난수를 생성하고 해당 숫자의 모든 소인수를 구하는 프로그램이라고 한다.)

java -jar math-game.jar

 

 

하나의 터미널을 더 띄워서 Arthas 실행

// math-game의 pid 조회
ps -ef| grep "math"

java -jar arthas-boot.jar ${pid}

 

 

help

여러 기능들을 확인 할수 있다. 

 

---

대시보드

대시보드를 몇 초주기로 snapshot할 것인가(i 옵션), 총 몇회 snapshot할 것인가(n옵션) 옵션을 사용할수 있으며 

타겟 jvm의 thread, memory, gc 등을 알 수 있다고한다.

 

 

---

thread

thread의 정보와 stack 정보(어디서부터 호출이 되었는지)

 

 

현재 메인스레드는 "대기상태"이며 Thread.sleep이 동작하고 있다.

 

스레드의 상태 (출처 :https://m.blog.naver.com/PostView.nhn?blogId=qbxlvnf11&logNo=220921178603&proxyReferer=https:%2F%2Fwww.google.com%2F)

 

---

jad

클래스를 디컴파일한다.

thrad에서 찾은 demo.MathGame 클래스를 디컴파일

 

 

       package demo;

       import java.util.ArrayList;
       import java.util.List;
       import java.util.Random;
       import java.util.concurrent.TimeUnit;

       public class MathGame {
           private static Random random = new Random();
           private int illegalArgumentCount = 0;

           public static void main(String[] args) throws InterruptedException {
               MathGame game = new MathGame();
               while (true) {
/*16*/             game.run();
/*17*/             TimeUnit.SECONDS.sleep(1L);
               }
           }

           public void run() throws InterruptedException {
               try {
/*23*/             int number = random.nextInt() / 10000;
/*24*/             List<Integer> primeFactors = this.primeFactors(number);
/*25*/             MathGame.print(number, primeFactors);
               }
               catch (Exception e) {
/*28*/             System.out.println(String.format("illegalArgumentCount:%3d, ", this.illegalArgumentCount) + e.getMessage());
               }
           }

           public static void print(int number, List<Integer> primeFactors) {
               StringBuffer sb = new StringBuffer(number + "=");
/*34*/         for (int factor : primeFactors) {
/*35*/             sb.append(factor).append('*');
               }
/*37*/         if (sb.charAt(sb.length() - 1) == '*') {
/*38*/             sb.deleteCharAt(sb.length() - 1);
               }
/*40*/         System.out.println(sb);
           }

           public List<Integer> primeFactors(int number) {
/*44*/         if (number < 2) {
/*45*/             ++this.illegalArgumentCount;
                   throw new IllegalArgumentException("number is: " + number + ", need >= 2");
               }
               ArrayList<Integer> result = new ArrayList<Integer>();
/*50*/         int i = 2;
/*51*/         while (i <= number) {
/*52*/             if (number % i == 0) {
/*53*/                 result.add(i);
/*54*/                 number /= i;
/*55*/                 i = 2;
                       continue;
                   }
/*57*/             ++i;
               }
/*61*/         return result;
           }
       }

---

watch

메소드의 반환 오브젝트 확인

// demo.MathGame 클레스의 primeFactors method를 감시하며 감시결과의 Object는 2depth까지 확인
// (최대 4depth), defualt 감시항목은 {params, target, returnObj}
watch demo.MathGame primeFactors -x 2

 

 

첫 번째 결과는 parameter로 -122486이 들어왔으며 result는 null 이다.

두 번째 결과는 parameter로 1이 들어왔으며 resultsms [3,5,7,17,113] 이다

 

당시 Math-Game 로그

 

 

여기까지가 퀵스타트의 기술된 내용들이다. 

위의 내용 외에도 memory, monitor, trace 등 많은 옵션들이 있으니 시간 날 때 하나씩 확인해보도록 하자.

---

 

profile

최적화 팀에서 봤던 내용으로 jvm stack을 확인하며 동시에 어느 메소드에서 시간이 가장 오래 걸렸는지 확인해볼 수 있다.

 

다양한 옵션들이 있다.

 

어떠한 것을 감시할 것인가 list를 조회해볼수 있다.

최적화 팀에서는 wall 옵션을사용하였다.

 

https://github.com/async-profiler/async-profiler

GitHub - async-profiler/async-profiler: Sampling CPU and HEAP profiler for Java featuring AsyncGetCallTrace + perf_events

 

설명: 스레드 상태(실행 중, 휴면 중 또는 차단됨)에 관계없이 지정된 기간마다 모든 스레드를 동등하게 샘플링하도록 지시합니다.  ( 즉 어느 구간이 가장 오래 지연되는지 알 수 있는 것)

 

프로파일링 시작 event는 wall로

 

프로파일링 정지 결과 파일의 포멧은 html로

 

 

html을 열어보면

 

 

 

x축은 소요시간 y축은 하단부터 상단까지 JVM 호출 스택이다 즉 X축이 긴것이 소요시간이 오래 걸린것이다.

main함수를 찾아 클릭하면  Timeunit의 sleep을 사용한 것을 확인할수 있다.

 

그런데 MathGame Class의 run 메소드가 보이지 않는 이유를 모르겠다. 

기간에 대한 샘플링이기 때문에 sleep에 비해서 run의 동작시간이 너무 짧아서 보이지 않는 것일까.?