一、他是什么?
Arthas 是全新的在线诊断工具,采用命令行交互模式,支持web端在线诊断,同时提供丰富的 Tab 自动补全功能,进一步方便进行问题的定位和诊断。
二、Arthas(阿尔萨斯)能干什么
Arthas 是Alibaba开源的Java诊断工具,它能帮你解决以下问题:
- 这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
- 我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
- 遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
- 线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
- 有什么办法可以监控到容器和中间件(AliTomcat、HSF、Notify 等)的实时运行状态?
- 有什么办法可以监控到JVM的实时运行状态?
- 怎么快速定位应用的热点,生成火焰图?
- 怎样直接从JVM内查找某个类的实例?
三、下载、安装
略过
四、启动
- 选择机器登录
- 执行命令行
-
- 执行 sh as.sh
- 两次 回车
五、快速了解
1、想快速了解系统、应用运行状况
- dashboard——当前系统的实时数据面板
- thread——查看当前 JVM 的线程堆栈信息
- jvm——查看当前 JVM 的信息
- sysprop——查看和修改JVM的系统属性
- getstatic——查看类的静态属性
2、类、方法冲突、class文件、classloader继承问题等
- sc——查看JVM已加载的类信息
- sm——查看已加载类的方法信息
- dump——dump 已加载类的 byte code 到特定目录
- redefine——加载外部的.class文件,redefine到JVM里
- jad——反编译指定已加载类的源码
- classloader——查看classloader的继承树,urls,类加载信息,使用classloader去getResource
3、查看方法执行参数、异常、返回值、调用路径等
非常重要,请注意,这些命令,都通过字节码增强技术来实现的,会在指定类的方法中插入一些切面来实现数据统计和观测,因此在线上、预发使用时,请尽量明确需要观测的类、方法以及条件,诊断结束要执行 shutdown 或将增强过的类执行 reset 命令。
- monitor——方法执行监控
- watch——方法执行数据观测
- trace——方法内部调用路径,并输出方法路径上的每个节点上耗时
- stack——输出当前方法被调用的调用路径
- tt——方法执行数据的时空隧道,记录下指定方法每次调用的入参和返回信息,并能对这些不同的时间下调用进行观测
4、options
- options——查看或设置Arthas全局开关
5、Arthas 基础命令
- help——查看命令帮助信息
- cls——清空当前屏幕区域
- session——查看当前会话的信息
- reset——重置增强类,将被 Arthas 增强过的类全部还原,Arthas 服务端关闭时会重置所有增强过的类
- version——输出当前目标 Java 进程所加载的 Arthas 版本号
- quit——退出当前 Arthas 客户端,其他 Arthas 客户端不受影响
- shutdown——关闭 Arthas 服务端,所有 Arthas 客户端全部退出
- keymap——Arthas快捷键列表及自定义快捷键
6、管道
Arthas支持使用管道对上述命令的结果进行进一步的处理,如sm org.apache.log4j.Logger | grep <init>
- grep——搜索满足条件的结果
- plaintext——将命令的结果去除颜色
- wc——按行统计输出结果
7、后台异步任务
当线上出现偶发的问题,比如需要watch某个条件,而这个条件一天可能才会出现一次时,异步后台任务就派上用场了,详情请参考这里
- 使用 > 将结果重写向到日志文件,使用 & 指定命令是后台运行,session断开不影响任务执行(生命周期默认为1天)
- jobs——列出所有job
- kill——强制终止任务
- fg——将暂停的任务拉到前台执行
- bg——将暂停的任务放到后台执行
六、命令行
1、系统指标 - dashboard 命令
参数说明
参数名称 | 参数说明 |
[i:] | 刷新实时数据的时间间隔 (ms),默认5000ms |
[n:] | 刷新实时数据的次数 |
输入dashboard,按回车/enter,会展示当前进程的信息,按ctrl+c可以中断执行。
$ dashboard
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
889 RMI TCP Connection(15)-30.10.166. RMI Runtime 9 RUNNABLE 48 0:5 false true
1077 Timer-for-arthas-dashboard-0 system 9 RUNNABLE 24 0:0 false true
1074 as-selector-daemon system 9 RUNNABLE 12 0:0 false true
284 JMX server connection timeout 284 RMI Runtime 9 TIMED_WAITI 8 0:3 false true
16 Timer-1 main 5 TIMED_WAITI 5 0:9 false true
47 Pandora pandora-qos-reporter Pool main 5 TIMED_WAITI 0 0:0 false true
48 JmonitorClient-CheckThread Pool [ main 5 TIMED_WAITI 0 0:0 false true
49 JmonitorClient-HeartBeat Pool [Th main 5 TIMED_WAITI 0 0:0 false true
50 JmonitorClient-ReaderThread Pool main 5 TIMED_WAITI 0 0:0 false true
957 RMI TCP Connection(16)-30.10.166. RMI Runtime 9 RUNNABLE 0 0:2 false true
51 JmonitorClient-WriterThread Pool main 5 TIMED_WAITI 0 0:0 false true
52 ContainerBackgroundProcessor[Stan main 5 TIMED_WAITI 0 0:0 false true
53 http-bio-8080-Acceptor-0 main 5 RUNNABLE 0 0:2 false true
54 http-bio-8080-AsyncTimeout main 5 TIMED_WAITI 0 0:0 false true
11 GC Daemon system 2 TIMED_WAITI 0 0:0 false true
Memory used total max usage GC
heap 59M 223M 1820M 3.26% gc.ps_scavenge.count 118
ps_eden_space 14M 114M 668M 2.11% gc.ps_scavenge.time(ms) 1890
ps_survivor_space 6M 6M 6M 96.08% gc.ps_marksweep.count 5
ps_old_gen 39M 103M 1365M 2.86% gc.ps_marksweep.time(ms) 1140
nonheap 234M 240M 0M 97.46%
code_cache 46M 47M 240M 19.49%
metaspace 167M 172M 0M 97.36%
Runtime Tomcat
os.name Mac OS X connector http-bio-8080
os.version 10.10.5 QPS 0.00
java.version 1.8.0_60 RT(ms) 1.13
java.home error/s 0.00
received/s 0B
systemload.average 3.44 sent/s 0B
processors 4 threadpool http-bio-8080
uptime 16020s busy 0
数据说明 | |
ID | Java级别的线程ID,注意这个ID不能跟jstack中的nativeID一一对应 |
NAME | 线程名 |
GROUP | 线程组名 |
PRIORITY | 线程优先级, 1~10之间的数字,越大表示优先级越高 |
STATE | 线程的状态 |
CPU% | 线程消耗的cpu占比,采样100ms,将所有线程在这100ms内的cpu使用量求和,再算出每个线程的cpu使用占比。 |
TIME | 线程运行总时间,数据格式为分:秒 |
INTERRUPTE | 线程当前的中断位状态 |
DAEMON | 是否是daemon线程 |
数据说明 | |
Memory | 内存区域 heap:堆 ps_eden_space:eden区 ps_survivor_space:S区 ps_old_gen:old区 nonheap:非堆内存 code_cache:缓存 metaspace:元数据 |
used | 已使用 |
total | 总共 |
max | 最大 |
usage | 使用率 |
GC | GC 垃圾收集器的详细信息, 包括垃圾回收次数gc.ps_scavenge.count、 垃圾回收消耗时间gc.ps_scavenge.time、 标记-清除算法的次数gc.ps_marksweep.count、 标记-清除算法的消耗时间gc.ps_marksweep.time |
Runtime | |
Tomcat |
Java 8之后支持获取JVM内部线程CPU时间,这些线程只有名称和CPU时间,没有ID及状态等信息(显示ID为-1)。 通过内部线程可以观测到JVM活动,如GC、JIT编译等占用CPU情况,方便了解JVM整体运行状况。
- 当JVM 堆(heap)/元数据(metaspace)空间不足或OOM时,可以看到GC线程的CPU占用率明显高于其他的线程。
- 当执行trace/watch/tt/redefine等命令后,可以看到JIT线程活动变得更频繁。因为JVM热更新class字节码时清除了此class相关的JIT编译结果,需要重新编译。
JVM内部线程包括下面几种:
- JIT编译线程: 如 C1CompilerThread0, C2CompilerThread0
- GC线程: 如GCThread0, G1YoungRemSetSampling
- 其它内部线程: 如VMPeriodicTaskThread, VMThread, ServiceThread
PS:堆(Heap)和非堆(Non-heap)内存
按照官方的说法:“Java 虚拟机具有一个堆,堆是运行时数据区域,所有类实例和数组的内存均从此处分配。堆是在 Java 虚拟机启动时创建的。”“在JVM中堆之外的内存称为非堆内存(Non-heap memory)”。可以看出JVM主要管理两种类型的内存:堆和非堆。简单来说堆就是Java代码可及的内存,是留给开发人员使用的;非堆就是JVM留给 自己用的,所以方法区、JVM内部处理或优化所需的内存(如JIT编译后的代码缓存)、每个类结构(如运行时常数池、字段和方法数据)以及方法和构造方法 的代码都在非堆内存中。
堆内存分配
JVM初始分配的内存由-Xms指定,默认是物理内存的1/64;JVM最大分配的内存由-Xmx指 定,默认是物理内存的1/4。默认空余堆内存小于40%时,JVM就会增大堆直到-Xmx的最大限制;空余堆内存大于70%时,JVM会减少堆直到 -Xms的最小限制。因此服务器一般设置-Xms、-Xmx相等以避免在每次GC 后调整堆的大小。
非堆内存分配
JVM使用-XX:PermSize设置非堆内存初始值,默认是物理内存的1/64;由XX:MaxPermSize设置最大非堆内存的大小,默认是物理内存的1/4。
JVM内存限制(最大值)
首先JVM内存限制于实际的最大物理内存(废话!呵呵),假设物理内存无限大的话,JVM内存的最大值跟操作系统有很大的关系。简单的说就32位处理器虽然 可控内存空间有4GB,但是具体的操作系统会给一个限制,这个限制一般是2GB-3GB(一般来说Windows系统下为1.5G-2G,Linux系统 下为2G-3G),而64bit以上的处理器就不会有限制了。
2、线程堆栈 - thread 命令
参数说明
参数名称 | 参数说明 |
id | 线程id |
[n:] | 指定最忙的前N个线程并打印堆栈 |
[b] | 找出当前阻塞其他线程的线程 |
[i <value>] | 指定cpu使用率统计的采样间隔,单位为毫秒,默认值为200 |
[--all] | 显示所有匹配的线程 |
cpu使用率是如何统计出来的?
这里的cpu使用率与linux 命令top-H-p<pid> 的线程%CPU类似,一段采样间隔时间内,当前JVM里各个线程的增量cpu时间与采样间隔时间的比例。
工作原理说明:
- 首先第一次采样,获取所有线程的CPU时间(调用的是java.lang.management.ThreadMXBean#getThreadCpuTime()及sun.management.HotspotThreadMBean.getInternalThreadCpuTimes()接口)
- 然后睡眠等待一个间隔时间(默认为200ms,可以通过-i指定间隔时间)
- 再次第二次采样,获取所有线程的CPU时间,对比两次采样数据,计算出每个线程的增量CPU时间
- 线程CPU使用率 = 线程增量CPU时间 / 采样间隔时间 * 100%
注意: 这个统计也会产生一定的开销(JDK这个接口本身开销比较大),因此会看到as的线程占用一定的百分比,为了降低统计自身的开销带来的影响,可以把采样间隔拉长一些,比如5000毫秒。
另外一种查看Java进程的线程cpu使用率方法:可以使用show-busy-java-threads这个脚本
使用说明:
3、JVM
查看当前JVM信息
使用说明:
http://mw.alibaba-inc.com/products/arthas/_book/cmds/jvm.html?spm=a1zco.8292279.0.0.658a6771uQySZ7
4、sc
查看JVM已加载的类信息
“Search-Class” 的简写,这个命令能搜索出所有已经加载到 JVM 中的 Class 信息,这个命令支持的参数有 [d]、[E]、[f] 和 [x:]。
参数说明
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
[d] | 输出当前类的详细信息,包括这个类所加载的原始文件来源、类的声明、加载的ClassLoader等详细信息。 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
[f] | 输出当前类的成员变量信息(需要配合参数-d一起使用) |
[x:] | 指定输出静态变量时属性的遍历深度,默认为 0,即直接使用 toString 输出 |
class-pattern支持全限定名,如com.taobao.test.AAA,也支持com/taobao/test/AAA这样的格式,这样,我们从异常堆栈里面把类名拷贝过来的时候,不需要在手动把/替换为.啦。
sc 默认开启了子类匹配功能,也就是说所有当前类的子类也会被搜索出来,想要精确的匹配,请打开options disable-sub-class true开关
使用说明:
http://mw.alibaba-inc.com/products/arthas/_book/cmds/sc.html?spm=a1zco.8292279.0.0.658a6771uQySZ7
5、sm
查看已加载类的方法信息
“Search-Method” 的简写,这个命令能搜索出所有已经加载了 Class 信息的方法信息。
sm 命令只能看到由当前类所声明 (declaring) 的方法,父类则无法看到。
参数说明
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
[d] | 展示每个方法的详细信息 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
使用说明:
http://mw.alibaba-inc.com/products/arthas/_book/cmds/sm.html?spm=a1zco.8292279.0.0.658a6771uQySZ7
6、jad
反编译指定已加载类的源码
jad 命令将 JVM 中实际运行的 class 的 byte code 反编译成 java 代码,便于你理解业务逻辑;
- 在 Arthas Console 上,反编译出来的源码是带语法高亮的,阅读更方便
- 当然,反编译出来的 java 代码可能会存在语法错误,但不影响你进行阅读理解
参数说明
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
[c:] | 类所属 ClassLoader 的 hashcode |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
使用说明:
http://mw.alibaba-inc.com/products/arthas/_book/cmds/jad.html?spm=a1zco.8292279.0.0.658a6771uQySZ7
使用小技巧
1、可以查看是哪个类加载器加载的该类
2、如果有多个jar包内有该类,可以查看是哪个jar包的生效
3、可以查看线上或者预发代码,启动后是否生效,或者是否有人在我代码里下毒。
4、类太长想看某一个方法,安排
7、classloader
查看classloader的继承树,urls,类加载信息
classloader 命令将 JVM 中所有的classloader的信息统计出来,并可以展示继承树,urls等。
可以让指定的classloader去getResources,打印出所有查找到的resources的url。对于ResourceNotFoundException比较有用。
参数说明
参数名称 | 参数说明 |
[l] | 按类加载实例进行统计 |
[t] | 打印所有ClassLoader的继承树 |
[a] | 列出所有ClassLoader加载的类,请谨慎使用 |
[c:] | ClassLoader的hashcode |
[c: r:] | 用ClassLoader去查找resource |
使用说明:
8、monitor
方法执行监控
对匹配 class-pattern/method-pattern的类、方法的调用进行监控。
monitor 命令是一个非实时返回命令,实时返回命令是输入之后立即返回,而非实时返回的命令,则是不断的等待目标 Java 进程返回信息,直到用户输入 Ctrl+C 为止。服务端是以任务的形式在后台跑任务,植入的代码随着任务的中止而被不会被执行,所以任务关闭后,不会对原有性能产生太大影响,而且原则上,任何 Arthas 的命令也不会引起任何原有业务逻辑的改变。
监控的维度说明
监控项 | 说明 |
timestamp | 时间戳 |
class | Java类 |
method | 方法(构造方法、普通方法) |
total | 调用次数 |
success | 成功次数 |
fail | 失败次数 |
rt | 平均RT |
fail-rate | 失败率 |
参数说明
方法拥有一个命名参数 [c:],意思是统计周期(cycle of output),拥有一个整形的参数值
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
[c:] | 统计周期,默认值为120秒 |
使用说明:
9、watch
方法执行数据观测
让你能方便的观察到指定方法的调用情况。能观察到的范围为:返回值、抛出异常、入参,通过编写 OGNL 表达式进行对应变量的查看。
参数说明
watch 的参数比较多,主要是因为它能在 4 个不同的场景观察对象
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
express | 观察表达式 |
condition-express | 条件表达式 |
[b] | 在方法调用之前观察 |
[e] | 在方法异常之后观察 |
[s] | 在方法返回之后观察 |
[f] | 在方法结束之后(正常返回和异常返回)观察 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
[x:] | 指定输出结果的属性遍历深度,默认为 1 |
这里重点要说明的是观察表达式,观察表达式的构成主要由 ognl 表达式组成,所以你可以这样写"{params,returnObj}",只要是一个合法的 ognl 表达式,都能被正常支持。
观察的维度也比较多,主要体现在参数 advice 的数据结构上。Advice 参数最主要是封装了通知节点的所有信息。
请参考表达式核心变量中关于该节点的描述。
- 特殊用法请参考:http://gitlab.alibaba-inc.com/middleware-container/arthas/issues/263
- OGNL表达式官网:OGNL - Apache Commons OGNL - Language Guide
特别说明:
- watch 命令定义了4个观察事件点,即 -b 方法调用前,-e 方法异常后,-s 方法返回后和 -f 方法结束后
- 4个观察事件点 -b、-e、-s 默认关闭,-f 默认打开,当指定观察点被打开后,在相应事件点会对观察表达式进行求值并输出
- 这里要注意方法入参和方法出参的区别,有可能在中间被修改导致前后不一致,除了 -b 事件点 params 代表方法入参外,其余事件都代表方法出参
- 当使用 -b 时,由于观察事件点是在方法调用前,此时返回值或异常均不存在
使用说明:
代码示例:
public void execute() {
List<String> list = new ArrayList<String>();
list.add("a");
list.add("b");
List<String> list2 = new ArrayList<String>();
list2.add("c");
list2.add("d");
int len = add(list, list2);
}
private static int add(List<String> list, List<String> list2) {
list.addAll(list2);
return list.size();
}
观察方法出参和返回值
$ watch com.alibaba.sample.petstore.web.store.module.screen.ItemList add "{params,returnObj}" -x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 44 ms.
@ArrayList[
@Object[][
@ArrayList[isEmpty=false;size=4],
@ArrayList[isEmpty=false;size=2],
],
@Integer[4],
]
观察方法前入参和返回值
$ watch com.alibaba.sample.petstore.web.store.module.screen.ItemList add "{params,returnObj}" -x 2 -b
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 48 ms.
@ArrayList[
@Object[][
@ArrayList[isEmpty=false;size=2],
@ArrayList[isEmpty=false;size=2],
],
null,
]
对比前一个例子,params[0] 其size为2(入参),返回值为空(事件点为方法执行前,因此获取不到返回值)
同时观察方法调用前和方法返回后
$ watch com.alibaba.sample.petstore.web.store.module.screen.ItemList add "{params,returnObj}" -x 2 -b -s
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 59 ms.
@ArrayList[
@Object[][
@ArrayList[isEmpty=false;size=2],
@ArrayList[isEmpty=false;size=2],
],
null,
]
@ArrayList[
@Object[][
@ArrayList[isEmpty=false;size=4],
@ArrayList[isEmpty=false;size=2],
],
@Integer[4],
]
这里输出结果中,第一次输出的是方法调用前的观察表达式的结果,第二次输出的是方法返回后的表达式的结果
结果的顺序和命令中 -s -b 的顺序没有关系,只与事件本身的先后顺序有关
调整-x的值,观察具体的方法参数值
$ watch com.alibaba.sample.petstore.web.store.module.screen.ItemList add "{params,returnObj}" -x 3
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 59 ms.
@ArrayList[
@Object[][
@ArrayList[
@String[a],
@String[b],
@String[c],
@String[d],
],
@ArrayList[
@String[c],
@String[d],
],
],
@Integer[4],
]
-x表示遍历深度,可以调整来打印具体的参数和结果内容。
条件表达式的例子
请求过多,想要咱们想看的数据
$ watch com.alibaba.sample.petstore.biz.impl.UserManagerImpl testAdd "{params, returnObj}" "params[0].equals('aaa')" -x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 29 ms.
@ArrayList[
@Object[][
@String[aaa],
@String[bbb],
],
@Integer[6],
]
只有满足条件的调用,才会有响应。
观察异常信息的例子
$ watch com.alibaba.sample.petstore.biz.impl.UserManagerImpl testAdd "{params, throwExp}" -e -x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 29 ms.
@ArrayList[
@Object[][
@String[aaa],
@String[bbb],
],
java.lang.NullPointerException
at com.alibaba.sample.petstore.biz.impl.UserManagerImpl.testAdd(UserManagerImpl.java:75)
at com.alibaba.sample.petstore.biz.impl.UserManagerImpl.register(UserManagerImpl.java:60)
at com.alibaba.sample.petstore.web.user.module.action.RegisterAction.doRegister(RegisterAction.java:45)
at com.alibaba.sample.petstore.web.user.module.action.RegisterAction$$FastClassByCGLIB$$ad5428f1.invoke(<generated>)
at net.sf.cglib.reflect.FastMethod.invoke(FastMethod.java:53)
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke(MethodInvoker.java:70)
at com.alibaba.citrus.service.moduleloader.impl.adapter.AbstractModuleEventAdapter.executeAndReturn(AbstractModuleEventAdapter.java:100)
at com.alibaba.citrus.service.moduleloader.impl.adapter.AbstractModuleEventAdapter.execute(AbstractModuleEventAdapter.java:58)
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke(PerformActionValve.java:63)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.service.pipeline.impl.valve.ChooseValve.invoke(ChooseValve.java:98)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.service.pipeline.impl.valve.LoopValve.invokeBody(LoopValve.java:105)
at com.alibaba.citrus.service.pipeline.impl.valve.LoopValve.invoke(LoopValve.java:83)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PageAuthorizationValve.invoke(PageAuthorizationValve.java:105)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.CheckCsrfTokenValve.invoke(CheckCsrfTokenValve.java:123)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.AnalyzeURLValve.invoke(AnalyzeURLValve.java:126)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.SetLoggingContextValve.invoke(SetLoggingContextValve.java:66)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PrepareForTurbineValve.invoke(PrepareForTurbineValve.java:52)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.webx.impl.WebxControllerImpl.service(WebxControllerImpl.java:43)
at com.alibaba.citrus.webx.impl.WebxRootControllerImpl.handleRequest(WebxRootControllerImpl.java:53)
at com.alibaba.citrus.webx.support.AbstractWebxRootController.service(AbstractWebxRootController.java:165)
at com.alibaba.citrus.webx.servlet.WebxFrameworkFilter.doFilter(WebxFrameworkFilter.java:152)
at com.alibaba.citrus.webx.servlet.FilterBean.doFilter(FilterBean.java:148)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at com.alibaba.citrus.webx.servlet.SetLoggingContextFilter.doFilter(SetLoggingContextFilter.java:61)
at com.alibaba.citrus.webx.servlet.FilterBean.doFilter(FilterBean.java:148)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
at com.taobao.tomcat.valves.ContextLoadFilterValve.invoke(ContextLoadFilterValve.java:152)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:429)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1085)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1760)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1719)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745),
]
express中,表示异常信息的变量是throwExp
按照耗时进行过滤
$ watch com.alibaba.sample.petstore.web.store.module.screen.ItemList add "{params,returnObj}" #cost>200 -x 3
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 59 ms.
@ArrayList[
@Object[][
@ArrayList[
@String[a],
@String[b],
@String[c],
@String[d],
],
@ArrayList[
@String[c],
@String[d],
],
],
@Integer[4],
]
cost>200(单位是ms)表示只有当耗时大于200ms时才会输出,过滤掉执行时间小于200ms的调用
观察当前对象中的全局属性
如果想查看方法运行前后,当前对象中的全局属性,可以使用target关键字,代表当前对象
$ watch com.taobao.container.web.arthas.rest.MyAppsController myFavoriteApps 'target'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 128 ms.
ts=2017-10-31 18:45:55;result=@MyAppsController[
myFavAppsMapper=@$Proxy131[org.apache.ibatis.binding.MapperProxy@563e97f3],
getAppNameAndIdByEmpId=@$Proxy135[HardCodedTarget(type=GetAppNameAndIdByEmpId, url=http://astro.alibaba-inc.com)],
enableWebConsoleAppsMapper=@$Proxy132[org.apache.ibatis.binding.MapperProxy@7d51e4a8],
]
然后使用target.field_name访问当前对象的某个全局属性
$ watch com.taobao.container.web.arthas.rest.MyAppsController myFavoriteApps 'target.myFavAppsMapper'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 126 ms.
ts=2017-10-31 18:46:17;result=@$Proxy131[
m1=@Method[public boolean java.lang.Object.equals(java.lang.Object)],
m2=@Method[public java.lang.String java.lang.Object.toString()],
m5=@Method[public abstract java.util.List com.taobao.container.dal.arthas.mapper.MyFavAppsMapper.listFavApps(java.util.Map)],
m3=@Method[public abstract int com.taobao.container.dal.arthas.mapper.MyFavAppsMapper.delete(java.lang.String,java.lang.String,java.lang.String)],
m4=@Method[public abstract long com.taobao.container.dal.arthas.mapper.MyFavAppsMapper.insert(com.taobao.container.dal.arthas.domain.MyFavAppsDO)],
m0=@Method[public native int java.lang.Object.hashCode()],
]
10、trace
方法内部路径耗时
方法内部调用路径,并输出方法路径上的每个节点上耗时
trace 命令能主动搜索 class-pattern/method-pattern 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
参数说明
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
condition-express | 条件表达式 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
[n:] | 命令执行次数 |
#cost | 方法执行耗时 |
这里重点要说明的是观察表达式,观察表达式的构成主要由 ognl 表达式组成,所以你可以这样写"{params,returnObj}",只要是一个合法的 ognl 表达式,都能被正常支持。
观察的维度也比较多,主要体现在参数 advice 的数据结构上。Advice 参数最主要是封装了通知节点的所有信息。
请参考表达式核心变量中关于该节点的描述。
- 特殊用法请参考:http://gitlab.alibaba-inc.com/middleware-container/arthas/issues/263
- OGNL表达式官网:OGNL - Apache Commons OGNL - Language Guide
很多时候我们只想看到某个方法的rt大于某个时间之后的trace结果,现在Arthas可以按照方法执行的耗时来进行过滤了,例如trace *StringUtils isBlank '$cost>100'表示当执行时间超过100ms的时候,才会输出trace的结果。
注意:
- watch/stack/trace这个三个命令都支持$cost
- 如果是Arthas 3.0,请把$cost改为#cost
注意事项
trace 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷,但其每次只能跟踪一级方法的调用链路。
使用参考
代码示例:
public static void main(String[] args) {
List<String> list = new ArrayList<String>();
list.add("a");
list.add("b");
List<String> list2 = new ArrayList<String>();
list2.add("c");
list2.add("d");
int len = add(list, list2);
}
private static int add(List<String> list, List<String> list2) {
int i = 10;
while (i >= 0) {
try {
hehe(i);
} catch (Throwable t) {
t.printStackTrace();
}
i--;
}
list.addAll(list2);
return list.size();
}
private static void hehe(int i) {
if (i == 0) {
throw new RuntimeException("ZERO");
}
}
监测 add 方法:
$ trace com.alibaba.sample.petstore.web.store.module.screen.ItemList add params.length==2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 144 ms.
`---Tracing...
`---[2ms]com.alibaba.sample.petstore.web.store.module.screen.ItemList:add()
+---[0,0,0ms,11]com.alibaba.sample.petstore.web.store.module.screen.ItemList:hehe() [throws Exception]
+---[1ms]java.lang.Throwable:printStackTrace()
+---[0ms]java.util.List:addAll()
`---[0ms]java.util.List:size()
按照耗时过滤:
$ trace com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>4
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 159 ms.
trace com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>4
`---thread_name=http-nio-8080-exec-5;id=2c;is_daemon=true;priority=5;TCCL=com.taobao.pandora.boot.embedded.tomcat.TomcatEmbeddedWebappClassLoader
`---[8.866586ms] com.alibaba.sample.petstore.web.store.module.screen.ItemList:execute()
+---[2.847106ms] com.alibaba.sample.petstore.biz.StoreManager:getAllProductItems()
+---[0.765544ms] com.alibaba.sample.petstore.dal.dao.ProductDao:getProductById()
+---[0.021204ms] com.alibaba.sample.petstore.dal.dataobject.Product:getCategoryId()
+---[1.341532ms] com.alibaba.sample.petstore.dal.dao.CategoryDao:getCategoryById()
`---[min=0.005428ms,max=0.094064ms,total=0.105228ms,count=3] com.alibaba.citrus.turbine.Context:put()
只会展示耗时大于4ms的调用路径,有助于在排查问题的时候,只关注异常情况
- 是不是很眼熟,没错,在 JProfiler 等收费软件中你曾经见识类似的功能,这里你将可以通过命令就能打印出指定调用路径。 友情提醒下,trace 在执行的过程中本身是会有一定的性能开销,在统计的报告中并未像 JProfiler 一样预先减去其自身的统计开销。所以这统计出来有些许的不准,渲染路径上调用的类、方法越多,性能偏差越大。但还是能让你看清一些事情的。
- [2ms] 的含义,2 的含义是:当前节点在当前步骤的耗时,单位为毫秒
- [0,0,0ms,11]xxx:yyy() [throws Exception],对该方法中相同的方法调用进行了合并,0,0,0ms,11 表示方法调用耗时,min,max,total,count;throws Exception 表明该方法调用中存在异常返回
- 这里存在一个统计不准确的问题,就是所有方法耗时加起来可能会小于该监测方法的总耗时,这个是由于 Arthas 本身的逻辑会有一定的耗时
11、stack
查看方法调用栈
输出当前方法被调用的调用路径
很多时候我们都知道一个方法被执行,但这个方法被执行的路径非常多,或者你根本就不知道这个方法是从那里被执行了,此时你需要的是 stack 命令。
参数说明
参数名称 | 参数说明 |
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
condition-express | 条件表达式 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
[n:] | 执行次数限制 |
这里重点要说明的是观察表达式,观察表达式的构成主要由 ognl 表达式组成,所以你可以这样写"{params,returnObj}",只要是一个合法的 ognl 表达式,都能被正常支持。
观察的维度也比较多,主要体现在参数 advice 的数据结构上。Advice 参数最主要是封装了通知节点的所有信息。
请参考表达式核心变量中关于该节点的描述。
- 特殊用法请参考:http://gitlab.alibaba-inc.com/middleware-container/arthas/issues/263
- OGNL表达式官网:OGNL - Apache Commons OGNL - Language Guide
使用例子
注意:如果表达式里面包含了引号,那么需要把整个表达式用引号括起来,如果表达式中没有包含引号,那么可以不用引号。当然,一个好的习惯是,不管表达式中有没有引号,都使用引号括起来。
$ stack com.alibaba.sample.petstore.dal.dao.ProductDao getProductById 'params[0]=="K9-BD-01"'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 51 ms.
thread_name="http-bio-8080-exec-4" thread_id=0x4a;is_daemon=true;priority=5;
@com.alibaba.sample.petstore.dal.dao.ibatis.IbatisProductDao.getProductById()
at com.alibaba.sample.petstore.web.store.module.screen.ItemList.execute(ItemList.java:50)
at com.alibaba.sample.petstore.web.store.module.screen.ItemList$$FastClassByCGLIB$$40b2f45f.invoke(<generated>:-1)
at net.sf.cglib.reflect.FastMethod.invoke(FastMethod.java:53)
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke(MethodInvoker.java:70)
at com.alibaba.citrus.service.moduleloader.impl.adapter.DataBindingAdapter.executeAndReturn(DataBindingAdapter.java:41)
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.performScreenModule(PerformScreenValve.java:111)
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.invoke(PerformScreenValve.java:74)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke(PerformActionValve.java:73)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
......
thread_name="http-bio-8080-exec-2" thread_id=0x48;is_daemon=true;priority=5;
@com.alibaba.sample.petstore.dal.dao.ibatis.IbatisProductDao.getProductById()
at com.alibaba.sample.petstore.web.store.module.screen.ItemList.execute(ItemList.java:50)
at com.alibaba.sample.petstore.web.store.module.screen.ItemList$$FastClassByCGLIB$$40b2f45f.invoke(<generated>:-1)
at net.sf.cglib.reflect.FastMethod.invoke(FastMethod.java:53)
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke(MethodInvoker.java:70)
at com.alibaba.citrus.service.moduleloader.impl.adapter.DataBindingAdapter.executeAndReturn(DataBindingAdapter.java:41)
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.performScreenModule(PerformScreenValve.java:111)
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.invoke(PerformScreenValve.java:74)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke(PerformActionValve.java:73)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.service.pipeline.impl.valve.ChooseValve.invoke(ChooseValve.java:98)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
......
按照耗时查询:
$ stack com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>30
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 123 ms.
stack com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>30
thread_name=http-nio-8080-exec-10;id=31;is_daemon=true;priority=5;TCCL=com.taobao.pandora.boot.embedded.tomcat.TomcatEmbeddedWebappClassLoader
@com.alibaba.sample.petstore.web.store.module.screen.ItemList.execute()
at com.alibaba.sample.petstore.web.store.module.screen.ItemList$$FastClassByCGLIB$$40b2f45f.invoke(<generated>:-1)
at net.sf.cglib.reflect.FastMethod.invoke(FastMethod.java:53)
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke(MethodInvoker.java:70)
at com.alibaba.citrus.service.moduleloader.impl.adapter.DataBindingAdapter.executeAndReturn(DataBindingAdapter.java:41)
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.performScreenModule(PerformScreenValve.java:111)
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.invoke(PerformScreenValve.java:74)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke(PerformActionValve.java:73)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.service.pipeline.impl.valve.ChooseValve.invoke(ChooseValve.java:98)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.service.pipeline.impl.valve.LoopValve.invokeBody(LoopValve.java:105)
at com.alibaba.citrus.service.pipeline.impl.valve.LoopValve.invoke(LoopValve.java:83)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PageAuthorizationValve.invoke(PageAuthorizationValve.java:105)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.CheckCsrfTokenValve.invoke(CheckCsrfTokenValve.java:123)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.AnalyzeURLValve.invoke(AnalyzeURLValve.java:126)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.SetLoggingContextValve.invoke(SetLoggingContextValve.java:66)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.turbine.pipeline.valve.PrepareForTurbineValve.invoke(PrepareForTurbineValve.java:52)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invokeNext(PipelineImpl.java:157)
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl$PipelineContextImpl.invoke(PipelineImpl.java:210)
at com.alibaba.citrus.webx.impl.WebxControllerImpl.service(WebxControllerImpl.java:43)
at com.alibaba.citrus.webx.impl.WebxRootControllerImpl.handleRequest(WebxRootControllerImpl.java:53)
at com.alibaba.citrus.webx.support.AbstractWebxRootController.service(AbstractWebxRootController.java:165)
.........
只会打印出耗时超过30ms的堆栈情况
tt
方法记录和回放
方法执行数据的时空隧道,记录下指定方法每次调用的入参和返回信息,并能对这些不同的时间下调用进行观测
watch 虽然很方便和灵活,但需要提前想清楚观察表达式的拼写,这对排查问题而言要求太高,因为很多时候我们并不清楚问题出自于何方,只能靠蛛丝马迹进行猜测。
这个时候如果能记录下当时方法调用的所有入参和返回值、抛出的异常会对整个问题的思考与判断非常有帮助。
于是乎,TimeTunnel 命令就诞生了。
记录方法的调用
- 基本用法对于一个最基本的使用来说,就是记录下当前方法的每次调用环境现场。
$ tt -t -n 3 *Test print
Press Ctrl+D or Ctrl+X to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 115 ms.
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1007 | 2015-07-26 12:23:21 | 138 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1008 | 2015-07-26 12:23:22 | 143 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1009 | 2015-07-26 12:23:23 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
$
- 命令参数解析
-
- -ttt 命令有很多个主参数,-t 就是其中之一。这个参数的表明希望记录下类 *Test 的 print 方法的每次执行情况。
- -n 3当你执行一个调用量不高的方法时可能你还能有足够的时间用 CTRL+C 中断 tt 命令记录的过程,但如果遇到调用量非常大的方法,瞬间就能将你的 JVM 内存撑爆。此时你可以通过 -n 参数指定你需要记录的次数,当达到记录次数时 Arthas 会主动中断tt命令的记录过程,避免人工操作无法停止的情况。
- 表格字段说明
表格字段 | 字段解释 |
INDEX | 时间片段记录编号,每一个编号代表着一次调用,后续tt还有很多命令都是基于此编号指定记录操作,非常重要。 |
TIMESTAMP | 方法执行的本机时间,记录了这个时间片段所发生的本机时间 |
COST(ms) | 方法执行的耗时 |
IS-RET | 方法是否以正常返回的形式结束 |
IS-EXP | 方法是否以抛异常的形式结束 |
OBJECT | 执行对象的hashCode(),注意,曾经有人误认为是对象在JVM中的无力内存地址,但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体 |
CLASS | 执行的类名 |
METHOD | 执行的方法名 |
- 条件表达式不知道大家是否有在使用过程中遇到以下困惑
-
- Arthas 似乎很难区分出重载的方法
- 我只需要观察特定参数,但是 tt 却全部都给我记录了下来条件表达式也是用 OGNL 来编写,核心的判断对象依然是 Advice 对象。除了 tt 命令之外,watch、trace、stack 命令也都支持条件表达式。
- 解决方法重载tt -t *Test print params[0].length==1通过制定参数个数的形式解决不同的方法签名,如果参数个数一样,你还可以这样写tt -t *Test print 'params[1] instanceof Integer'
- 解决指定参数tt -t *Test print params[0].mobile=="13989838402"
- 构成条件表达式的 Advice 对象前边看到了很多条件表达式中,都适用了 params[0],有关这个变量的介绍,请参考表达式核心变量
检索调用记录
当你用 tt 记录了一大片的时间片段之后,你希望能从中筛选出自己需要的时间片段,这个时候你就需要对现有记录进行检索。
假设我们有这些记录
$ tt -l
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1000 | 2015-07-26 01:16:27 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1001 | 2015-07-26 01:16:27 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1002 | 2015-07-26 01:16:28 | 119 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1003 | 2015-07-26 01:16:28 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1004 | 2015-07-26 12:21:56 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1005 | 2015-07-26 12:21:57 | 138 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1006 | 2015-07-26 12:21:58 | 130 | true | false | 0x42cc13a0 | GaOgnlUtilsTest | print |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
Affect(row-cnt:7) cost in 2 ms.
$
我需要筛选出 printAddress 方法的调用信息
$ tt -s method.name=="printAddress"
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1001 | 2015-07-26 01:16:27 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
| 1003 | 2015-07-26 01:16:28 | 0 | false | true | 0x42cc13a0 | GaOgnlUtilsTest | printAddress |
+----------+----------------------+------------+----------+----------+-----------------+--------------------------------+--------------------------------+
Affect(row-cnt:2) cost in 55 ms.
$
你需要一个 -s 参数。同样的,搜索表达式的核心对象依旧是 Advice 对象。
查看调用信息
对于具体一个时间片的信息而言,你可以通过 -i 参数后边跟着对应的 INDEX 编号查看到他的详细信息。
$ tt -i 1003
+-----------------+------------------------------------------------------------------------------------------------------+
| INDEX | 1003 |
+-----------------+------------------------------------------------------------------------------------------------------+
| GMT-CREATE | 2015-07-26 01:16:28 |
+-----------------+------------------------------------------------------------------------------------------------------+
| COST(ms) | 0 |
+-----------------+------------------------------------------------------------------------------------------------------+
| OBJECT | 0x42cc13a0 |
+-----------------+------------------------------------------------------------------------------------------------------+
| CLASS | GaOgnlUtilsTest |
+-----------------+------------------------------------------------------------------------------------------------------+
| METHOD | printAddress |
+-----------------+------------------------------------------------------------------------------------------------------+
| IS-RETURN | false |
+-----------------+------------------------------------------------------------------------------------------------------+
| IS-EXCEPTION | true |
+-----------------+------------------------------------------------------------------------------------------------------+
| PARAMETERS[0] | Address@53448f87 |
+-----------------+------------------------------------------------------------------------------------------------------+
| THROW-EXCEPTION | java.lang.RuntimeException: test |
| | at GaOgnlUtilsTest.printAddress(Unknown Source) |
| | at GaOgnlUtilsTest.<init>(Unknown Source) |
| | at GaOgnlUtilsTest.main(Unknown Source) |
+-----------------+------------------------------------------------------------------------------------------------------+
Affect(row-cnt:1) cost in 1 ms.
$
重做一次调用
当你稍稍做了一些调整之后,你可能需要前端系统重新触发一次你的调用,此时得求爷爷告奶奶的需要前端配合联调的同学再次发起一次调用。而有些场景下,这个调用不是这么好触发的。
tt 命令由于保存了当时调用的所有现场信息,所以我们可以自己主动对一个 INDEX 编号的时间片自主发起一次调用,从而解放你的沟通成本。此时你需要 -p 参数。
$ tt -i 1003 -p
+-----------------+---------------------------------------------------------------------------------------------------------+
| RE-INDEX | 1003 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| GMT-REPLAY | 2015-07-26 17:29:51 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| OBJECT | 0x42cc13a0 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| CLASS | GaOgnlUtilsTest |
+-----------------+---------------------------------------------------------------------------------------------------------+
| METHOD | printAddress |
+-----------------+---------------------------------------------------------------------------------------------------------+
| PARAMETERS[0] | Address@53448f87 |
+-----------------+---------------------------------------------------------------------------------------------------------+
| IS-RETURN | false |
+-----------------+---------------------------------------------------------------------------------------------------------+
| IS-EXCEPTION | true |
+-----------------+---------------------------------------------------------------------------------------------------------+
| THROW-EXCEPTION | java.lang.RuntimeException: test |
| | at GaOgnlUtilsTest.printAddress(GaOgnlUtilsTest.java:78) |
| | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) |
| | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) |
| | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) |
| | at java.lang.reflect.Method.invoke(Method.java:483) |
| | at com.github.ompc.Arthas.util.GaMethod.invoke(GaMethod.java:81) |
| | at com.github.ompc.Arthas.command.TimeTunnelCommand$6.action(TimeTunnelCommand.java:592) |
| | at com.github.ompc.Arthas.server.DefaultCommandHandler.execute(DefaultCommandHandler.java:175) |
| | at com.github.ompc.Arthas.server.DefaultCommandHandler.executeCommand(DefaultCommandHandler.java:83) |
| | at com.github.ompc.Arthas.server.GaServer$4.run(GaServer.java:329) |
| | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) |
| | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) |
| | at java.lang.Thread.run(Thread.java:745) |
+-----------------+---------------------------------------------------------------------------------------------------------+
replay time fragment[1003] success.
Affect(row-cnt:1) cost in 3 ms.
$
你会发现结果虽然一样,但调用的路径发生了变化,有原来的程序发起变成了 Arthas 自己的内部线程发起的调用了。
- 需要强调的点
-
- ThreadLocal 信息丢失很多框架偷偷的将一些环境变量信息塞到了发起调用线程的 ThreadLocal 中,由于调用线程发生了变化,这些 ThreadLocal 线程信息无法通过 Arthas 保存,所以这些信息将会丢失。一些常见的 CASE 比如:鹰眼的 TraceId 等。
- 引用的对象需要强调的是,tt 命令是将当前环境的对象引用保存起来,但仅仅也只能保存一个引用而已。如果方法内部对入参进行了变更,或者返回的对象经过了后续的处理,那么在 tt 查看的时候将无法看到当时最准确的值。这也是为什么 watch 命令存在的意义。