开发者学堂课程【线上问题排查利器 Alibaba Arthas(下):Trace 命令的语法和案例】学习笔记,与课程紧密连接,让用户快速学习知识。
课程地址:https://developer.aliyun.com/learning/course/747/detail/13204
Trace 命令的语法和案例
内容介绍:
一.学习目标
二.介绍
三.参数说明
四.举例
五.小结
一.学习目标
学习 trace 这条命令的使用,主要功能是对一个方法内部的调用路径进行追踪,并且输出方法路径上的每个节点上的耗时,这一点对于在服务器端诊断服务器的运行时间非常重要,只有在实际的应用场景中才可以看到哪点耗时较大,则在该点进行优化。
二.介绍
首先是功能,能够跟踪类指定的方法,整个调用路径,对阅读源代码有帮助,若在开发工具里看源代码逐层点较麻烦,此处会较清晰的将整个调用路径显示出,也会显示性能开销和耗时。这是主要作用。观察表达式的构成主要由 ognl 表达式组成,很多命令都支持 ognl ,合法的 ognl 表达式都可以在trace 命令里使用,同时还可以对执行的平均时间进行过滤,如关注哪部分最耗时,则只显示大于某个时间点的执行方法,只跟踪这样的路径,便于更方便的排除,watch 、stack 、trace 都支持耗时条件过滤。
三.参数说明
第一个 class-pattern ,是类名表达式的匹配。
第二个 method-pattern ,是方法名表达式的匹配。
第三个 condition-express ,是条件表达式,使用 ognl 表达式。还有是[E] ,是大写的,表示开启正则表达式匹配,默认的情况下是通配符的匹配方式。
还有是 [n :] ,设置命令执行的次数。最后一个 cost ,指方法执行的耗时,单位是毫秒。
四.举例
下面通过案例学习 trace 的应用场景,举四个例子。
第一个例子,trace函数指定类的指定方法。是数学游戏,已经进入了追踪,追踪数学游戏中的run方法看效果。
[arthas@5769] $ trace demo.MathGame run
追踪了数学游戏类里的 run 方法,分析运行结果。
ts = 2020-03-21 08:10:07 是时间,thread_name=main 是线程的名字,run 方法是在主线程里执行的。
如下图原代码中 run 方法也是在主线程当中调用的。
然后是主线程的ID,ID=1,priority=5 是线程的优先级,第五级,TCCL=sun.misc.Launcher $AppClassLoader@70dea4e 是类加载器。
[2.14519ms] demo.MathGame:run()是调用run方法的耗时,并且用红色标出了整个执行路径当中最耗时的部分,即计算质因数分解较耗时,并且第一次调用抛了异常。根据原码也可知异常是自己抛出的,如果小于2则会抛异常。
//分解质因数
public void run() throws InterruptedException {
try {
//随机生成一个整数,有可能正,有可能负
int number = random.nextint()/10000;
//调用方法进行质因数分解
List<Integer> primeFactors = primeFactors(number);
//打印结果
print(number, primeFactors);
} catch (Exception e) {
System.out.println(String.format("illegalArgumentCount:%3d,",illegalArgumentCount)+ e.getMessage());
}
}
//打印质因数分解的结果
public static void print(int number, List<Integer> primeFactors) {
StringBuffer sb = new StringBuffer(number + "=");
for (int factor : primeFactors) {
sb.append(factor).append('*');
}
//打印结果
print(number, primeFactors);
} catch(Exception e) {
System.out.println(String.format("illegalArgumentCount:%3d,",illegalArgumentCount)+ e.getMessage()):
}
}
//打印质因数分解的结果
public static void print(int number, List<Integer> primeFactors) {
StringBuffer sb = new StringBuffer(number + "=");
for(int factor : primeFactors) {
sb.append(factor).append('*');
}
if (sb.charAt(sb.length() - 1) == '*') {
sb.deleteCharAt(sb.length(() - 1);
}
System.out.println(sb);
}
//计算 number 的质因数分解
public List<Integer> primefactors(int number)!
//如果小于2,则抛出异常,并且计数加1
if (number < 2) {
illegalArgumentCount++;
throw new IllegalArgumentException("number is: " + number + ", need >= 2");
}
//用于保存每个质数
List<Integer> result = new ArrayList<Integer>():
因此可得代码一次抛了异常,一次没有,则会继续往下走,执行了同一级的 print 方法,继续又抛异常,没有执行print 方法,再继续执行print 方法,可得跟踪每一个执行路径上最耗时的部分用红色标出了。这是第一个例子。
对于第二个例子,刚才执行了4次后强制退出,如果有些方法它调用的次数特别多,可以指定一个-n的参数来指定捕获结果的次数,如让它捕获一次或捕获两次就退出这个命令,则在刚才的基础上加一个-n 2 ,表示捕获两次退出,此时不需按任何操作的 q ,不按 q 也可执行。追踪两次。
退出下面也有解释,最多执行两次,程序退出了,现在执行的两次都没有执行打印的方法都抛出了异常,再执行时一次执行打印的方法,一次执行的抛出异常。这是第二个命令。
第三个操作,在默认的情况下 trace.不包含jdk里的函数调用,运行的结果里全部是自己写的方法,因为追踪是追踪自己写的方法,出错也是自己的代码出错,不会将jdk里的执行方法和它的类追踪出,但是有时想知道执行哪些方法,将jdk也显示出,此时需加一个参数 skip ,跳过 jdk 的方法,这个参数是skipjdkmethod ,可以设置为false,默认true 表示跳过,将其包含则trace-skipjdkmethod false demo.mathgame run ,执行两次则会停下,下图是执行的结果。
会发现多了 Random 里的 nextint 的方法,这个方法也是在函数里写了的方法,但是之前没有显示,观察原码,run 方法里确实调用了 nextint ,也调用了 primefactors 及print ,总共调用了三个方法,这三个方法在追踪的代码里都可以看到。这是演示的第三个例子。
//分解质因数
public void run() throws InterruptedException {
try {
//随机生成一个整数,有可能正,有可能负
int number = random.nextint()/10000;
//调用方法进行质因数分解
List<Integer>primeFactors=primeFactors(number);
//打印结果
print(number, primeFactors);
} catch (Exception e) {
System.out.println(String.format("illegalArgumentCount;%3d,",illegalArgumentCount) + e.getMessage());
}
}
第四个例子,可以根据调用的耗时情况对时间只显示大于某个时间的最终的方法,此时可以使用 cost 耗时的参数进行操作。也调用两次,“# cost >.5”,不一定三次刚好全部大于0.5,先不设置执行的次数,发现不是每一次都大于0.5,没有大于0.5就不会输出,看到的全部都是大于0.5。
若改为>1ms,只要小于1ms都不输出,1是指 run 方法的耗时,并非红色部分。
五.小结
trace 部分就介绍到此,在实际开发中用的较多,进行小结主要回顾 trace 命令有哪几个参数,如参数的名称及参数的说明,首先第一个参数叫 class-pattern ,表示类名表达式的匹配,第二个method-pattern ,他代表方法名的表达式匹配,还有condition-express,叫条件表达式,是三个必须的参数。
也支持正则表达式和命令执行的次数,还支持#cost ,可以用来过滤,是过滤的条件,只追踪满足条件的耗时方法,刚刚演示的是大写,也可能是小写或等于,也有可能,trace 命令就介绍这些。