イントロダクション#
Arthas は、アプリケーションのメモリ、gc、スレッドの状態情報をグローバルな視点からリアルタイムで確認できるオンライン監視診断製品です。アプリケーションコードを変更することなく、ビジネス上の問題を診断でき、メソッド呼び出しの引数、例外、メソッド実行の所要時間、クラスロード情報などを確認できるため、オンライン問題のトラブルシューティング効率が大幅に向上します。
問題解決:
- ローカル開発環境から本番環境にアクセスできず、問題が発生した際にデバッグが困難
- 特定の問題が異なる環境で簡単に再現できない
- 問題解決のためにログを追加する必要があり、リリースに関わる
基本コマンド#
ダウンロードとインストール:#
マシンにインストール:
curl -O https://arthas.aliyun.com/arthas-boot.jar
コマンドリスト:#
1. jvm 関連:#
- dashboard - 現在のシステムのリアルタイムデータパネル、デフォルトで 5 秒ごとに更新
ID: JavaレベルのスレッドID。このIDはjstackのnativeIDと一対一で対応しないことに注意。
NAME: スレッド名
GROUP: スレッドグループ名
PRIORITY: スレッドの優先度、1〜10の間の数字。大きいほど優先度が高い。setPriority(1-10)
STATE: スレッドの状態
CPU%: スレッドのCPU使用率。例えば、サンプリング間隔が1000msで、あるスレッドの増分CPU時間が100msであれば、CPU使用率=100/1000=10%
DELTA_TIME: 前回のサンプリング以降のスレッドの実行増分CPU時間、データ形式は秒
TIME: スレッドの総CPU時間、データ形式は分:秒
INTERRUPTED: スレッドの現在の中断状態
DAEMON: デーモンスレッドかどうか
C1 C2 CompilerThread:
ガベージコレクションの回数gc.ps_scavenge.count、ガベージコレクションにかかる時間gc.ps_scavenge.time、マーク-スイープアルゴリズムの回数gc.ps_marksweep.count、マーク-スイープアルゴリズムにかかる時間
- heapdump - Java ヒープをダンプ、jmap コマンドのヒープダンプ機能に似ています
heapdump xx-output/dump.hprof
生成されたファイルは arthas-output ディレクトリにあり、ブラウザで開くことができます: http://localhost:8563/xx-output/
-
jvm - 現在の JVM の情報を表示
Thread:
COUNT: 現在アクティブなスレッド数
DAEMON-COUNT: 現在アクティブなデーモンスレッド数
PEAK-COUNT: JVM 起動以来生存していた最大スレッド数
STARTED-COUNT: JVM 起動以来合計で起動されたスレッド数
DEADLOCK-COUNT: 現在のデッドロックスレッド数
ファイル記述子:
MAX-FILE-DESCRIPTOR-COUNT:JVM プロセスが最大で開けるファイル記述子の数
OPEN-FILE-DESCRIPTOR-COUNT:現在開いているファイル記述子の数 -
logger - logger を表示および変更
logger レベルを更新
logger --name ROOT --level debug -
memory - JVM のメモリ情報を表示
-
thread - 現在の JVM のスレッドスタック情報を表示
thread: デフォルトで CPU 増分時間の降順に並べ替え
thread -n 3 : 現在最も忙しい上位 3 つのスレッドを表示し、スタックを印刷
thread id : 指定したスレッドの実行スタックを表示
thread -b : 現在他のスレッドをブロックしているスレッドを特定:現在は synchronized キーワードでブロックされているスレッドのみをサポート
thread -i : サンプリング時間間隔を指定
thread --state : 指定した状態のスレッドを表示 -
vmoption - JVM 内の診断関連のオプションを表示および変更
指定したオプションを更新
vmoption PrintGC true -
vmtool - JVM からオブジェクトをクエリし、forceGc を実行
vmtool --action forceGc
2. class/classloader 関連#
-
classloader - classloader の継承ツリー、urls、クラスロード情報を表示し、classloader を使用して getResource を取得
クラスロードタイプに基づいて統計情報を表示: classloader
クラスロードインスタンスに基づいて統計情報を表示: classloader -l
ClassLoader の継承ツリーを表示: classloader -t -
dump - 読み込まれたクラスのバイトコードを特定のディレクトリにダンプ
dump com.xx.xx.controller.ArthasController ArthasController.class ファイルを生成
-
jad - 指定された読み込まれたクラスのソースコードを逆コンパイル
デフォルトでは、逆コンパイル結果には ClassLoader 情報が含まれ、--source-only オプションを使用するとソースコードのみを印刷できます
jad --source-only com.xx.xx.controller.ArthasController
jad --source-only com.xx.xx.controller.ArthasController deadLock -
redefine - 外部の.class ファイルを読み込み、JVM に再定義
redefine コマンドは jad/watch/trace/monitor/tt などのコマンドと競合します。redefine を実行した後に上記のコマンドを実行すると、redefine されたバイトコードがリセットされます。
-
retransform - 外部の.class ファイルを読み込み、JVM に再変換
- 外部の.class ファイルを読み込む
retransform /Users/xx/IdeaProjects/ArthasController.class - retransform エントリを表示
retransform -l - retransform エンティティを削除:
retransform -d 1
retransform --deleteAll
注: - すべての retransform エントリをクリアせずに再度 retransform をトリガーすると、arthas stop 時に retransform されたクラスが依然として有効です。
- retransform をクリアせずに Arthas を停止した場合、再度起動して jad-mc-retransform を実行すると、jad で逆コンパイルした結果は変更前のコードになります。
- retransform では新しいフィールドやメソッドを追加することはできません。
- 外部の.class ファイルを読み込む
-
sc - JVM に読み込まれたクラス情報を表示
sc -d com.xx.xx.controller.*
sc -d com.xx.xx.controller.ArthasController -
sm - 読み込まれたクラスのメソッド情報を表示
sm com.xx.xx.controller.ArthasController *
3. monitor/watch/trace 関連#
注意してください。これらのコマンドは、バイトコード強化技術を使用して実現されており、指定されたクラスのメソッドにいくつかのアスペクトを挿入してデータ統計と観測を実現します。したがって、オンラインやプレリリースで使用する際は、観測するクラス、メソッド、および条件を明確にし、診断が終了したら stop を実行するか、強化されたクラスに reset コマンドを実行してください。
必ず - n を付けてコマンドを実行してください。そうしないと、呼び出し量が非常に多いメソッドに遭遇した場合、瞬時に JVM メモリが溢れてしまう可能性があります。
-
monitor - メソッド実行の監視
ArthasController の flag メソッドを監視し、5 秒ごとに 10 回印刷
monitor com.xx.xx.controller.ArthasController flag -n 10 --cycle 5
インターフェースパラメータ param [0] <=2 のリクエストを統計
monitor -c 5 demo.MathGame primeFactors "params[0] <= 2" -
stack - 現在のメソッドが呼び出された呼び出しパスを出力
多くの場合、メソッドが実行されることはわかっていますが、そのメソッドが実行されるパスは非常に多いか、そもそもそのメソッドがどこから実行されているのかわからないことがあります。
stack com.xx.xx.service.impl.WjVideoServiceImpl preprocessingVideo -n 5
-
trace - メソッド内部の呼び出しパスを出力し、メソッドパス上の各ノードの所要時間を出力
- trace は、RT が高いために発生するパフォーマンス問題の欠陥を特定し、発見するのに便利ですが、毎回 1 レベルのメソッド呼び出しチェーンのみを追跡できます。
- 多くの場合、特定のメソッドの RT が特定の時間を超えた後の trace 結果のみを見たいと思います。'#cost>100' を使用すると、実行時間が 100ms を超えた場合にのみ trace 結果が出力されます。
- 現在、trace java.lang.Thread getName はサポートされていません。
--exclude-class-pattern 指定されたクラスを除外
--skipJDKMethod true JDK 内の関数を trace
'#cost > 10' 実行時間が 10ms を超えた場合にのみ trace 結果が出力されます。
多段メソッドの実装チェーン呼び出しを追跡
trace -E com.xx.xx.service.impl.VideoServiceImpl|com.xx.xx.controller.AutoCutController|com.xx.xx.service.impl.WjVideoServiceImpl preprocessing|preprocessingVideo -n 5 '#cost>10' -
tt (TimeTunnel) - メソッド実行データの時空トンネルで、指定されたメソッドの各呼び出しの引数と戻り情報を記録し、これらの異なる時間での呼び出しを観測できます
tt -t com.kscs.capcut.service.impl.WjVideoServiceImpl preprocessingVideo -n 5
tt -l 呼び出し記録を検索 tt -s 'method.name=="preprocessingVideo"'
tt -i 1000 呼び出し情報を表示
tt -i 1004 -p 再度呼び出しを実行 -
watch - 指定された関数の呼び出し状況を観察します。観察できる範囲は:戻り値、例外のスロー、引数です。
- -f 関数が戻った後に観察
- -x 出力結果の属性の遍歴深さ
watch com.xx.xx.service.impl.WjVideoServiceImpl preprocessingVideo '{params,returnObj,throwExp}' -n 5 -x 3
問題解決:#
1. Arthas を利用して Java アプリケーションの CPU 負荷が高すぎる問題を正確に特定#
CPU占有率が最も高いスレッドを確認
1. thread / thread -n 3
2. thread id
1. メソッドがループで呼び出されている
2. 内部に無限ループがある
ttコマンドを使用してこのメソッドの呼び出し状況を監視します
tt -t com.xx.xx.controller.ArthasController deadAdd -n 5
オンラインでこのコマンドを実行する際は、必ず-nパラメータを付けることを忘れないでください。さもなければ、オンラインの膨大なトラフィックが瞬時にJVMメモリを圧迫する可能性があります。
メソッドを逆コンパイルして確認します
jad --source-only com.xx.xx.controller.ArthasController deadAdd
top --> top -Hp pid --> jstack pid 16 進数
2. Arthas を利用してメモリ問題を分析#
dashboardでGCデータを確認
gc.ps_scavenge.count gc.ps_marksweep.count
vmoptionコマンドを使用してGCログを動的に開く
vmoption PrintGC true
vmoption PrintGCDetails true
vmtoolを使用して強制GCを実行
vmtool --action forceGc
https://www.v2ex.com/t/792635
3. ログ出力レベルを動的に変更#
logger
デフォルトでは、loggerコマンドはSystemClassloaderの下で実行されます。アプリケーションが従来のwarアプリケーションまたはspring boot fat jarで起動される場合、classloaderを指定する必要があります。
logger -c 685f4c2e --name ROOT --level debug
4. ソースコードを逆コンパイルし、jvm が読み込んでいる内容が期待通りであるか確認します。#
jad --source-only com.xx.xx.controller.AutoCutController preprocessing
5. メソッド内の呼び出しパスと各メソッドの呼び出し所要時間。#
monitor :このコマンドはメソッドの実行状況を監視するために使用され、メソッドの呼び出し回数、成功回数、失敗回数、最大所要時間、最小所要時間、平均所要時間を含みます。通常、パフォーマンス問題を特定するために使用されます。
[arthas@19702]$ monitor com.xx.xx.service.impl.WjVideoServiceImpl preprocessingVideo -n 10 --cycle 10
QまたはCtrl+Cを押して中止します。
影響を受けたクラス数: 1 , メソッド数: 1 49 msでコスト、リスナーID: 3
タイムスタンプ クラス メソッド 合計 成功 失敗 平均RT( 失敗率
ms) テ
------------------------------------------------------------------------------------------------------------------
2023-07-17 16:21 com.xx.xx.service. preprocessingVideo 1 1 0 3755.98 0.00%
:14 impl.WjVideoServiceImpl
trace :このコマンドはメソッドの呼び出しパスと所要時間を追跡するために使用されます。メソッドの引数と戻り結果、メソッド内部で呼び出された他のメソッドとそれらの実行時間を記録します。
[arthas@19702]$ trace -E com.xx.xx.service.impl.VideoServiceImpl|com.xx.xx.controller.AutoCutController|com.xx.xx.service.impl.WjVideoServiceImpl preprocessing|preprocessingVideo -n 5 --skipJDKMethod false '1==1'
QまたはCtrl+Cを押して中止します。
影響を受けたクラス数: 4 , メソッド数: 4 157 msでコスト、リスナーID: 2
`---ts=2023-07-17 16:20:42;thread_name=http-nio-8183-exec-8;id=2b;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@3576ddc2
`---[1.069325ms] com.xx.xx.controller.AutoCutController$$EnhancerBySpringCGLIB$$333516af:preprocessing()
`---[83.17% 0.889312ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[43.36% 0.385619ms ] com.xx.xx.controller.AutoCutController:preprocessing()
+---[6.45% 0.024868ms ] org.slf4j.MDC:get() #31
+---[1.90% 0.007333ms ] com.xx.xx.common.vo.ProcessingVO:setTaskId() #31
+---[70.24% 0.270861ms ] com.xx.xx.service.VideoService:preprocessingVideo() #32
`---[2.93% 0.011295ms ] com.xx.xx.base.model.Result:success() #33
tt :このコマンドはメソッドの履歴呼び出し状況を記録し、メソッドの引数、戻り結果、例外情報を含みます。メソッドの現在の呼び出し状況だけでなく、メソッドの履歴呼び出し状況も確認でき、履歴呼び出しを再試行することもできます。
[arthas@19702]$ tt -t com.kscs.capcut.controller.AutoCutController preprocessing -n 5
QまたはCtrl+Cを押して中止します。
影響を受けたクラス数: 2 , メソッド数: 2 39 msでコスト、リスナーID: 4
インデックス タイムスタンプ コスト(ms IS-RE IS-EX オブジェクト クラス メソッド
) T P
------------------------------------------------------------------------------------------------------------------
1000 2023-07-17 16:23 0.20207 true false 0x5ec8b24c AutoCutController preprocessing
:17 4
1001 2023-07-17 16:23 1.94166 true false 0xe637be2a AutoCutController$$Enhan preprocessing
:17 4 cerBySpringCGLIB$$333516
6. コードのホットアップデート#
1. 読み込まれたクラスのソースコードを逆コンパイル
jad --source-only com.kscs.capcut.controller.ArthasController
2. ローカルコードを変更し、コンパイル、テスト。成功したらtargetディレクトリ内のコンパイル済み.classファイルを見つけます
3. ホットアップデート
retransform /Users/edy/IdeaProjects/ArthasController.class
2. retransformエントリを表示
retransform -l
3. retransformエンティティを削除:
retransform -d 1
retransform --deleteAll
サービスパフォーマンスへの影響#
Arthasがtrace/watch/tt/monitorなどのコマンドを実行する際、本質的にはメソッドの前後にコードを挿入しており、元のJVM内のJITコンパイルによって生成されたコードが無効になります。元のコードに戻し、再度JITコンパイルを行う必要があります。したがって、高い同時呼び出しがある関数呼び出しでは、揺れを引き起こす可能性があります。
したがって、一度に大量のクラスをtrace/watchすることは避けるべきです。
オンライン環境では、クラスター内で負荷の低いマシンを選択して分析を実行することをお勧めします。もし一台のマシンしかない場合は、慎重に使用してください。
使用するデモ#
public class ArthasController {
public static boolean flag = true;
private List<ProcessingVO> stringList = new ArrayList<>();
@RequestMapping(method = RequestMethod.POST, value = "flag")
public Result<Map<String, String>> flag(Integer param1, Integer param2) {
flag = !flag;
return Result.success();
}
@RequestMapping(method = RequestMethod.POST, value = "oom")
public Result<List<ProcessingVO>> oom() {
stringList.clear();
for (int i = 0; i < 1000000; i++) {
if (stringList.size() > 500000) {
continue;
}
ProcessingVO vo = new ProcessingVO();
vo.setVideoName("videoName" + i);
vo.setTaskId("taskId" + i);
stringList.add(vo);
}
return Result.success();
}
@RequestMapping(method = RequestMethod.POST, value = "deadLock")
public Result<Map<String, String>> deadLock() {
Thread thread1 = new Thread(() -> {
synchronized (String.class) {
log.info("thread1 get String lock");
try {
Thread.sleep(10000);
} catch (Exception e) {
e.printStackTrace();
}
synchronized (Integer.class) {
log.info("thread1 get Integer lock");
}
}
});
Thread thread2 = new Thread(() -> {
synchronized (Integer.class) {
log.info("thread2 get Integer lock");
try {
Thread.sleep(100);
} catch (Exception e) {
e.printStackTrace();
}
synchronized (String.class) {
log.info("thread2 get String lock");
}
}
});
thread1.setName("deadlock-thread1");
thread2.setName("deadlock-thread2");
thread1.start();
thread2.start();
return Result.success();
}
@RequestMapping(method = RequestMethod.POST, value = "highCPU")
public Result<Map<String, String>> highCPU() {
Thread highCpuThread = new Thread(this::deadAdd);
highCpuThread.setName("HighCpu");
highCpuThread.start();
return Result.success();
}
//0<-1<-2<-0
private void deadAdd() {
ListNode node2 = new ListNode(2, null); //ノードを作成(データ+参照
ListNode node1 = new ListNode(1, node2);
ListNode node = new ListNode(0, node1);
node2.next = node;
while (node != null) {
if (flag) {
node = node.next;
} else {
break;
}
}
System.out.println("stop deadAdd");
}
class ListNode { //クラス名 :Javaクラスはカスタムデータ構造の一種
int val; //データ :ノードデータ
ListNode next; //オブジェクト :次のノードオブジェクトを参照。Javaにはポインタの概念はなく、Javaの参照はC言語のポインタに似ています
ListNode(int val, ListNode next) { //コンストラクタ :コンストラクタはクラス名と同じ
this.val = val; //受け取ったパラメータを現在のクラスのval変数に割り当てる
this.next = next;
}
}
}