51

使用 Arthas 在线排查问题，无需重启；动态跟踪Java代码；实时监控JVM状态

 5 years ago
source link: https://www.tuicool.com/articles/BzEFVjE
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

qu2uMfj.jpg!web

Arthas（阿尔萨斯） 能为你做什么？

Arthas  是Alibaba开源的Java诊断工具，深受开发者喜爱。

当你遇到以下类似问题而束手无策时， Arthas 可以帮助你解决：

  1. 这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？

  2. 我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？

  3. 遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？

  4. 线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！

  5. 是否有一个全局视角来查看系统的运行状况？

  6. 有什么办法可以监控到JVM的实时运行状态？

Arthas 支持JDK 6+，支持Linux/Mac/Winodws，采用命令行交互模式，同时提供丰富的  Tab 自动补全功能，进一步方便进行问题的定位和诊断。

Arthas 支持JDK 6+，支持Linux/Mac/Windows，采用命令行交互模式，同时提供丰富的  Tab 自动补全功能，进一步方便进行问题的定位和诊断。

  • Github: https://github.com/alibaba/arthas

  • 文档: https://alibaba.github.io/arthas/

在线实操地点:

https://alibaba.github.io/arthas/arthas-tutorials?language=cn

实用命令笔记

trace

方法内部调用路径，并输出方法路径上的每个节点上耗时

trace 命令能主动搜索  class-pattern ／ method-pattern 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

参数说明

参数名称 参数说明 class-pattern 类名表达式匹配 method-pattern 方法名表达式匹配 condition-express 条件表达式 [E] 开启正则表达式匹配，默认为通配符匹配 [n:] 命令执行次数 #cost 方法执行耗时

这里重点要说明的是观察表达式，观察表达式的构成主要由 ognl 表达式组成，所以你可以这样写 "{params,returnObj}" ，只要是一个合法的 ognl 表达式，都能被正常支持。

观察的维度也比较多，主要体现在参数 advice 的数据结构上。 Advice 参数最主要是封装了通知节点的所有信息。

请参考表达式核心变量中关于该节点的描述。

  • 特殊用法请参考：https://github.com/alibaba/arthas/issues/71

  • OGNL表达式官网：https://commons.apache.org/proper/commons-ognl/language-guide.html

很多时候我们只想看到某个方法的rt大于某个时间之后的trace结果，现在Arthas可以按照方法执行的耗时来进行过滤了，例如 trace *StringUtils isBlank '#cost>100' 表示当执行时间超过100ms的时候，才会输出trace的结果。

watch/stack/trace这个三个命令都支持 #cost

注意事项

trace 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。

使用参考

启动 Demo

启动快速入门里的 arthas-demo 。

trace函数

$ trace demo.MathGame run
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin42 ms.
`---ts=2018-12-04 00:44:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
`---[10.611029ms] demo.MathGame:run()
+---[0.05638ms] java.util.Random:nextInt()
+---[10.036885ms] demo.MathGame:primeFactors()
`---[0.170316ms] demo.MathGame:print()

过滤掉jdk的函数

$ trace -j demo.MathGame run
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin31 ms.
`---ts=2018-12-04 01:09:14;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
`---[5.190646ms] demo.MathGame:run()
+---[4.465779ms] demo.MathGame:primeFactors()
`---[0.375324ms] demo.MathGame:print()

  • -j : jdkMethodSkip, skip jdk method trace

据调用耗时过滤

$ trace demo.MathGame run'#cost > 10'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin41 ms.
`---ts=2018-12-04 01:12:02;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
`---[12.033735ms] demo.MathGame:run()
+---[0.006783ms] java.util.Random:nextInt()
+---[11.852594ms] demo.MathGame:primeFactors()
`---[0.05447ms] demo.MathGame:print()

只会展示耗时大于10ms的调用路径，有助于在排查问题的时候，只关注异常情况

  • 是不是很眼熟，没错，在 JProfiler 等收费软件中你曾经见识类似的功能，这里你将可以通过命令就能打印出指定调用路径。友情提醒下， trace 在执行的过程中本身是会有一定的性能开销，在统计的报告中并未像 JProfiler 一样预先减去其自身的统计开销。所以这统计出来有些许的不准，渲染路径上调用的类、方法越多，性能偏差越大。但还是能让你看清一些事情的。

  • [12.033735ms] 的含义， 12.033735 的含义是：当前节点在当前步骤的耗时，单位为毫秒

  • [0,0,0ms,11]xxx:yyy() [throws Exception]，对该方法中相同的方法调用进行了合并， 0,0,0ms,11 表示方法调用耗时， min,max,total,count ； throws Exception 表明该方法调用中存在异常返回

  • 这里存在一个统计不准确的问题，就是所有方法耗时加起来可能会小于该监测方法的总耗时，这个是由于 Arthas 本身的逻辑会有一定的耗时

trace多个类或者多个函数

trace命令只会trace匹配到的函数里的子调用，并不会向下trace多层。因为trace是代价比较贵的，多层trace可能会导致最终要trace的类和函数非常多。

可以用正则表匹配路径上的多个类和函数，一定程度上达到多层trace的效果。

trace -E com.test.ClassA|org.test.ClassB method1|method2|method3

thread

查看当前线程信息，查看线程的堆栈

参数说明

参数名称 参数说明 id 线程id [n:] 指定最忙的前N个线程并打印堆栈 [b] 找出当前阻塞其他线程的线程 [i <value> ] 指定cpu占比统计的采样间隔，单位为毫秒

cpu占比是如何统计出来的？

这里的cpu统计的是，一段采样间隔内，当前JVM里各个线程所占用的cpu时间占总cpu时间的百分比。其计算方法为：首先进行一次采样，获得所有线程的cpu的使用时间(调用的是 java.lang.management.ThreadMXBean#getThreadCpuTime 这个接口)，然后睡眠一段时间，默认100ms，可以通过 -i 参数指定，然后再采样一次，最后得出这段时间内各个线程消耗的cpu时间情况，最后算出百分比。

注意：这个统计也会产生一定的开销（JDK这个接口本身开销比较大），因此会看到as的线程占用一定的百分比，为了降低统计自身的开销带来的影响，可以把采样间隔拉长一些，比如5000毫秒。

如果想看从Java进程启动开始到现在的cpu占比情况：可以使用show-busy-java-threads这个脚本

使用参考

支持一键展示当前最忙的前N个线程并打印堆栈：

$thread -n 3
"as-command-execute-daemon" Id=29 cpuUsage=75% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
at com.taobao.arthas.core.command.monitor200.ThreadCommand$1.action(ThreadCommand.java:58)
at com.taobao.arthas.core.command.handler.AbstractCommandHandler.execute(AbstractCommandHandler.java:238)
at com.taobao.arthas.core.command.handler.DefaultCommandHandler.handleCommand(DefaultCommandHandler.java:67)
at com.taobao.arthas.core.server.ArthasServer$4.run(ArthasServer.java:276)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@6cd0b6f8

"as-session-expire-daemon" Id=25 cpuUsage=24% TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at com.taobao.arthas.core.server.DefaultSessionManager$2.run(DefaultSessionManager.java:85)

"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.Reference$Lock@69ba0f27
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)

当没有参数时，显示所有线程的信息。

$thread
Threads Total: 16, NEW: 0, RUNNABLE: 7, BLOCKED: 0, WAITING: 5, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
30 as-command-execute-daemon system 9 RUNNABLE 72 0:0 false true
23 as-session-expire-daemon system 9 TIMED_WAIT 27 0:0 false true
22 Attach Listener system 9 RUNNABLE 0 0:0 false true
11 pool-2-thread-1 main 5 TIMED_WAIT 0 0:0 false false
12 Thread-2 main 5 RUNNABLE 0 0:0 false true
13 pool-3-thread-1 main 5 TIMED_WAIT 0 0:0 false false
25 as-selector-daemon system 9 RUNNABLE 0 0:0 false true
14 Thread-3 main 5 TIMED_WAIT 0 0:0 false false
26 pool-5-thread-1 system 5 WAITING 0 0:0 false false
15 Thread-4 main 5 RUNNABLE 0 0:0 false false
1 main main 5 WAITING 0 0:2 false false
2 Reference Handler system 10 WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
4 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
20 NonBlockingInputStreamThread main 5 WAITING 0 0:0 false true
21 Thread-8 main 5 RUNNABLE 0 0:0 false true

thread id， 显示指定线程的运行堆栈

$thread 1
"main" Id=1 WAITING on java.util.concurrent.CountDownLatch$Sync@29fafb28
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.CountDownLatch$Sync@29fafb28
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)

thread -b, 找出当前阻塞其他线程的线程

有时候我们发现应用卡住了， 通常是由于某个线程拿住了某个锁， 并且其他线程都在等待这把锁造成的。为了排查这类问题， arthas提供了 thread -b ， 一键找出那个罪魁祸首。 

$ thread -b
"http-bio-8080-exec-4"Id=27 TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at test.arthas.TestThreadBlocking.doGet(TestThreadBlocking.java:22)
- locked java.lang.Object@725be470 <---- but blocks 4 other threads!
at javax.servlet.http.HttpServlet.service(HttpServlet.java:624)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at test.filter.TestDurexFilter.doFilter(TestDurexFilter.java:46)
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 org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
at com.taobao.tomcat.valves.ContextLoadFilterValve$FilterChainAdapter.doFilter(ContextLoadFilterValve.java:191)
at com.taobao.eagleeye.EagleEyeFilter.doFilter(EagleEyeFilter.java:81)
at com.taobao.tomcat.valves.ContextLoadFilterValve.invoke(ContextLoadFilterValve.java:150)
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.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
- locked org.apache.tomcat.util.net.SocketWrapper@7127ee12
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)

Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@31a6493e

注意， 目前只支持找出synchronized关键字阻塞住的线程， 如果是 java.util.concurrent.Lock ， 目前还不支持。

thread -i, 指定采样时间间隔

$ thread -n 3 -i 1000
"as-command-execute-daemon"Id=4759 cpuUsage=23% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:133)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:79)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:96)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:27)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:125)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:122)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:332)
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:756)

Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@546aeec1
...

watch

方法执行数据观测

让你能方便的观察到指定方法的调用情况。能观察到的范围为： 返回值 、 抛出异常 、 入参 ，通过编写 OGNL 表达式进行对应变量的查看。

参数说明

watch 的参数比较多，主要是因为它能在 4 个不同的场景观察对象

参数名称 参数说明 class-pattern 类名表达式匹配 method-pattern 方法名表达式匹配 express 观察表达式 condition-express 条件表达式 [b] 在 方法调用之前 观察 [e] 在 方法异常之后 观察 [s] 在 方法返回之后 观察 [f] 在 方法结束之后 (正常返回和异常返回)观察 [E] 开启正则表达式匹配，默认为通配符匹配 [x:] 指定输出结果的属性遍历深度，默认为 1

这里重点要说明的是观察表达式，观察表达式的构成主要由 ognl 表达式组成，所以你可以这样写 "{params,returnObj}" ，只要是一个合法的 ognl 表达式，都能被正常支持。

观察的维度也比较多，主要体现在参数 advice 的数据结构上。 Advice 参数最主要是封装了通知节点的所有信息。请参考表达式核心变量中关于该节点的描述。

  • 特殊用法请参考：https://github.com/alibaba/arthas/issues/71

  • OGNL表达式官网：https://commons.apache.org/proper/commons-ognl/language-guide.html

特别说明：

  • watch 命令定义了4个观察事件点，即 -b 方法调用前， -e 方法异常后， -s 方法返回后， -f 方法结束后

  • 4个观察事件点 -b 、 -e 、 -s 默认关闭， -f 默认打开，当指定观察点被打开后，在相应事件点会对观察表达式进行求值并输出

  • 这里要注意 方法入参 和 方法出参 的区别，有可能在中间被修改导致前后不一致，除了  -b 事件点  params 代表方法入参外，其余事件都代表方法出参

  • 当使用 -b 时，由于观察事件点是在方法调用前，此时返回值或异常均不存在

使用参考

启动 Demo

启动快速入门里的 arthas-demo 。

观察方法出参和返回值

$ watch demo.MathGame primeFactors"{params,returnObj}"-x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin44 ms.
ts=2018-12-03 19:16:51; [cost=1.280502ms] result=@ArrayList[
@Object[][
@Integer[535629513],
],
@ArrayList[
@Integer[3],
@Integer[19],
@Integer[191],
@Integer[49199],
],
]

观察方法入参

$ watch demo.MathGame primeFactors"{params,returnObj}"-x 2 -b
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin50 ms.
ts=2018-12-03 19:23:23; [cost=0.0353ms] result=@ArrayList[
@Object[][
@Integer[-1077465243],
],
null,
]

  • 对比前一个例子，返回值为空（事件点为方法执行前，因此获取不到返回值）

同时观察方法调用前和方法返回后

$ watch demo.MathGame primeFactors"{params,target,returnObj}"-x 2 -b -s -n 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin46 ms.
ts=2018-12-03 19:29:54; [cost=0.01696ms] result=@ArrayList[
@Object[][
@Integer[1544665400],
],
@MathGame[
random=@Random[java.util.Random@522b408a],
illegalArgumentCount=@Integer[13038],
],
null,
]
ts=2018-12-03 19:29:54; [cost=4.277392ms] result=@ArrayList[
@Object[][
@Integer[1544665400],
],
@MathGame[
random=@Random[java.util.Random@522b408a],
illegalArgumentCount=@Integer[13038],
],
@ArrayList[
@Integer[2],
@Integer[2],
@Integer[2],
@Integer[5],
@Integer[5],
@Integer[73],
@Integer[241],
@Integer[439],
],
]

  • 参数里 -n 2 ，表示只执行两次

  • 这里输出结果中，第一次输出的是方法调用前的观察表达式的结果，第二次输出的是方法返回后的表达式的结果

  • 结果的输出顺序和事件发生的先后顺序一致，和命令中 -s -b 的顺序无关

调整 -x 的值，观察具体的方法参数值 

$ watch demo.MathGame primeFactors"{params,target}"-x 3
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin58 ms.
ts=2018-12-03 19:34:19; [cost=0.587833ms] result=@ArrayList[
@Object[][
@Integer[47816758],
],
@MathGame[
random=@Random[
serialVersionUID=@Long[3905348978240129619],
seed=@AtomicLong[3133719055989],
multiplier=@Long[25214903917],
addend=@Long[11],
mask=@Long[281474976710655],
DOUBLE_UNIT=@Double[1.1102230246251565E-16],
BadBound=@String[bound must be positive],
BadRange=@String[bound must be greater than origin],
BadSize=@String[size must be non-negative],
seedUniquifier=@AtomicLong[-3282039941672302964],
nextNextGaussian=@Double[0.0],
haveNextNextGaussian=@Boolean[false],
serialPersistentFields=@ObjectStreamField[][isEmpty=false;size=3],
unsafe=@Unsafe[sun.misc.Unsafe@2eaa1027],
seedOffset=@Long[24],
],
illegalArgumentCount=@Integer[13159],
],
]

  • -x 表示遍历深度，可以调整来打印具体的参数和结果内容，默认值是1。

条件表达式的例子

$ watch demo.MathGame primeFactors"{params[0],target}""params[0]<0"
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin68 ms.
ts=2018-12-03 19:36:04; [cost=0.530255ms] result=@ArrayList[
@Integer[-18178089],
@MathGame[demo.MathGame@41cf53f9],
]

  • 只有满足条件的调用，才会有响应。

观察异常信息的例子

$ watch demo.MathGame primeFactors"{params[0],throwExp}"-e -x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin62 ms.
ts=2018-12-03 19:38:00; [cost=1.414993ms] result=@ArrayList[
@Integer[-1120397038],
java.lang.IllegalArgumentException: number is: -1120397038, need >= 2
at demo.MathGame.primeFactors(MathGame.java:46)
at demo.MathGame.run(MathGame.java:24)
at demo.MathGame.main(MathGame.java:16)
,
]

  • -e 表示抛出异常时才触发

  • express中，表示异常信息的变量是 throwExp

按照耗时进行过滤

$ watch demo.MathGame primeFactors'{params, returnObj}''#cost>200'-x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin66 ms.
ts=2018-12-03 19:40:28; [cost=2112.168897ms] result=@ArrayList[
@Object[][
@Integer[2141897465],
],
@ArrayList[
@Integer[5],
@Integer[428379493],
],
]

  • #cost>200 (单位是 ms )表示只有当耗时大于200ms时才会输出，过滤掉执行时间小于200ms的调用

观察当前对象中的属性

如果想查看方法运行前后，当前对象中的属性，可以使用 target 关键字，代表当前对象 

$ watch demo.MathGame primeFactors'target'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin52 ms.
ts=2018-12-03 19:41:52; [cost=0.477882ms] result=@MathGame[
random=@Random[java.util.Random@522b408a],
illegalArgumentCount=@Integer[13355],
]

然后使用 target.field_name 访问当前对象的某个属性 

$ watch demo.MathGame primeFactors'target.illegalArgumentCount'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) costin67 ms.
ts=2018-12-03 20:04:34; [cost=131.303498ms] result=@Integer[8]
ts=2018-12-03 20:04:35; [cost=0.961441ms] result=@Integer[8]

Thread

一目了然的了解系统的状态，哪些线程比较占cpu？他们到底在做什么？

$ thread -n 3
"as-command-execute-daemon" Id=29 cpuUsage=75% RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:440)
    at com.taobao.arthas.core.command.monitor200.ThreadCommand$1.action(ThreadCommand.java:58)
    at com.taobao.arthas.core.command.handler.AbstractCommandHandler.execute(AbstractCommandHandler.java:238)
    at com.taobao.arthas.core.command.handler.DefaultCommandHandler.handleCommand(DefaultCommandHandler.java:67)
    at com.taobao.arthas.core.server.ArthasServer$4.run(ArthasServer.java:276)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)

    Number of locked synchronizers = 1
    - java.util.concurrent.ThreadPoolExecutor$Worker@6cd0b6f8

"as-session-expire-daemon" Id=25 cpuUsage=24% TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at com.taobao.arthas.core.server.DefaultSessionManager$2.run(DefaultSessionManager.java:85)

"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@69ba0f27
    at java.lang.Object.wait(Native Method)
    -  waiting on java.lang.ref.Reference$Lock@69ba0f27
    at java.lang.Object.wait(Object.java:503)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)

jad

对类进行反编译:

$ jad javax.servlet.Servlet

ClassLoader:
+-java.net.URLClassLoader@6108b2d7
  +-sun.misc.Launcher$AppClassLoader@18b4aac2
    +-sun.misc.Launcher$ExtClassLoader@1ddf84b8

Location:
/Users/xxx/work/test/lib/servlet-api.jar

/*
 * Decompiled with CFR 0_122.
 */
package javax.servlet;

import java.io.IOException;
import javax.servlet.ServletConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;

public interface Servlet {
    public void init(ServletConfig var1) throws ServletException;

    public ServletConfig getServletConfig();

    public void service(ServletRequest var1, ServletResponse var2) throws ServletException, IOException;

    public String getServletInfo();

    public void destroy();
}

mc

Memory Compiler/内存编译器，编译 .java 文件生成 .class 。 

mc /tmp/Test.java

redefine

加载外部的 .class 文件，redefine jvm已加载的类。 

redefine /tmp/Test.class
redefine -c 327a647b /tmp/Test.class /tmp/Test\$Inner.class

sc

查找JVM中已经加载的类

$ sc -d org.springframework.web.context.support.XmlWebApplicationContext
 class-info        org.springframework.web.context.support.XmlWebApplicationContext
 code-source       /Users/xxx/work/test/WEB-INF/lib/spring-web-3.2.11.RELEASE.jar
 name              org.springframework.web.context.support.XmlWebApplicationContext
 isInterface       false
 isAnnotation      false
 isEnum            false
 isAnonymousClass  false
 isArray           false
 isLocalClass      false
 isMemberClass     false
 isPrimitive       false
 isSynthetic       false
 simple-name       XmlWebApplicationContext
 modifier          public
 annotation
 interfaces
 super-class       +-org.springframework.web.context.support.AbstractRefreshableWebApplicationContext
                     +-org.springframework.context.support.AbstractRefreshableConfigApplicationContext
                       +-org.springframework.context.support.AbstractRefreshableApplicationContext
                         +-org.springframework.context.support.AbstractApplicationContext
                           +-org.springframework.core.io.DefaultResourceLoader
                             +-java.lang.Object
 class-loader      +-org.apache.catalina.loader.ParallelWebappClassLoader
                     +-java.net.URLClassLoader@6108b2d7
                       +-sun.misc.Launcher$AppClassLoader@18b4aac2
                         +-sun.misc.Launcher$ExtClassLoader@1ddf84b8
 classLoaderHash   25131501

stack

查看方法 test.arthas.TestStack#doGet 的调用堆栈： 

$ stack test.arthas.TestStack doGet
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 286 ms.
ts=2018-09-18 10:11:45;thread_name=http-bio-8080-exec-10;id=d9;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@25131501
    @test.arthas.TestStack.doGet()
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:624)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        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.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:110)
        ...
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
        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:451)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1121)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
        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)

Trace

观察方法执行的时候哪个子调用比较慢:

Watch

观察方法 test.arthas.TestWatch#doGet 执行的入参，仅当方法抛出异常时才输出。 

$ watch test.arthas.TestWatch doGet {params[0], throwExp} -e
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 65 ms.
ts=2018-09-18 10:26:28;result=@ArrayList[
    @RequestFacade[org.apache.catalina.connector.RequestFacade@79f922b2],
    @NullPointerException[java.lang.NullPointerException],
]

Monitor

监控某个特殊方法的调用统计数据，包括总调用次数，平均rt，成功率等信息，每隔5秒输出一次。

$ monitor -c 5 org.apache.dubbo.demo.provider.DemoServiceImpl sayHello
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 109 ms.
 timestamp            class                                           method    total  success  fail  avg-rt(ms)  fail-rate
----------------------------------------------------------------------------------------------------------------------------
 2018-09-20 09:45:32  org.apache.dubbo.demo.provider.DemoServiceImpl  sayHello  5      5        0     0.67        0.00%

 timestamp            class                                           method    total  success  fail  avg-rt(ms)  fail-rate
----------------------------------------------------------------------------------------------------------------------------
 2018-09-20 09:45:37  org.apache.dubbo.demo.provider.DemoServiceImpl  sayHello  5      5        0     1.00        0.00%

 timestamp            class                                           method    total  success  fail  avg-rt(ms)  fail-rate
----------------------------------------------------------------------------------------------------------------------------
 2018-09-20 09:45:42  org.apache.dubbo.demo.provider.DemoServiceImpl  sayHello  5      5        0     0.43        0.00%

Time Tunnel(tt)

记录方法调用信息，支持事后查看方法调用的参数，返回值，抛出的异常等信息，仿佛穿越时空隧道回到调用现场一般。

$ tt -t org.apache.dubbo.demo.provider.DemoServiceImpl sayHello
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 75 ms.
 INDEX   TIMESTAMP            COST(ms)  IS-RET  IS-EXP   OBJECT         CLASS                          METHOD
-------------------------------------------------------------------------------------------------------------------------------------
 1000    2018-09-20 09:54:10  1.971195  true    false    0x55965cca     DemoServiceImpl                sayHello
 1001    2018-09-20 09:54:11  0.215685  true    false    0x55965cca     DemoServiceImpl                sayHello
 1002    2018-09-20 09:54:12  0.236303  true    false    0x55965cca     DemoServiceImpl                sayHello
 1003    2018-09-20 09:54:13  0.159598  true    false    0x55965cca     DemoServiceImpl                sayHello
 1004    2018-09-20 09:54:14  0.201982  true    false    0x55965cca     DemoServiceImpl                sayHello
 1005    2018-09-20 09:54:15  0.214205  true    false    0x55965cca     DemoServiceImpl                sayHello
 1006    2018-09-20 09:54:16  0.241863  true    false    0x55965cca     DemoServiceImpl                sayHello
 1007    2018-09-20 09:54:17  0.305747  true    false    0x55965cca     DemoServiceImpl                sayHello
 1008    2018-09-20 09:54:18  0.18468   true    false    0x55965cca     DemoServiceImpl                sayHello

Classloader

了解当前系统中有多少类加载器，以及每个加载器加载的类数量，帮助您判断是否有类加载器泄露。

$ classloader
 name                                                  numberOfInstances  loadedCountTotal
 BootstrapClassLoader                                  1                  3346
 com.taobao.arthas.agent.ArthasClassloader             1                  1262
 java.net.URLClassLoader                               2                  1033
 org.apache.catalina.loader.ParallelWebappClassLoader  1                  628
 sun.reflect.DelegatingClassLoader                     166                166
 sun.misc.Launcher$AppClassLoader                      1                  31
 com.alibaba.fastjson.util.ASMClassLoader              6                  15
 sun.misc.Launcher$ExtClassLoader                      1                  7
 org.jvnet.hk2.internal.DelegatingClassLoader          2                  2
 sun.reflect.misc.MethodUtil                           1                  1

Web Console

  • https://alibaba.github.io/arthas/web-console

Arthas 在入口类中, Attach到特定进程的JVM上，并加载Agent: 

package com.taobao.arthas.core;


import com.sun.tools.attach.VirtualMachine;

import com.sun.tools.attach.VirtualMachineDescriptor;

import com.taobao.arthas.common.AnsiLog;

import com.taobao.arthas.common.JavaVersionUtils;

import com.taobao.arthas.core.config.Configure;

import com.taobao.middleware.cli.CLI;

import com.taobao.middleware.cli.CLIs;

import com.taobao.middleware.cli.CommandLine;

import com.taobao.middleware.cli.Option;

import com.taobao.middleware.cli.TypedOption;


import java.io.UnsupportedEncodingException;

import java.net.URLEncoder;

import java.util.Arrays;

import java.util.Properties;


/**

* Arthas启动器

*/

public class Arthas {


private static final String DEFAULT_TELNET_PORT = "3658";

private static final String DEFAULT_HTTP_PORT = "8563";


private Arthas(String[] args) throws Exception {

attachAgent(parse(args));

}


private Configure parse(String[] args) {

Option pid = new TypedOption<Integer>().setType(Integer.class).setShortName("pid").setRequired(true);

Option core = new TypedOption<String>().setType(String.class).setShortName("core").setRequired(true);

Option agent = new TypedOption<String>().setType(String.class).setShortName("agent").setRequired(true);

Option target = new TypedOption<String>().setType(String.class).setShortName("target-ip");

Option telnetPort = new TypedOption<Integer>().setType(Integer.class)

.setShortName("telnet-port").setDefaultValue(DEFAULT_TELNET_PORT);

Option httpPort = new TypedOption<Integer>().setType(Integer.class)

.setShortName("http-port").setDefaultValue(DEFAULT_HTTP_PORT);

Option sessionTimeout = new TypedOption<Integer>().setType(Integer.class)

.setShortName("session-timeout").setDefaultValue("" + Configure.DEFAULT_SESSION_TIMEOUT_SECONDS);

CLI cli = CLIs.create("arthas").addOption(pid).addOption(core).addOption(agent).addOption(target)

.addOption(telnetPort).addOption(httpPort).addOption(sessionTimeout);

CommandLine commandLine = cli.parse(Arrays.asList(args));


Configure configure = new Configure();

configure.setJavaPid((Integer) commandLine.getOptionValue("pid"));

configure.setArthasAgent((String) commandLine.getOptionValue("agent"));

configure.setArthasCore((String) commandLine.getOptionValue("core"));

configure.setSessionTimeout((Integer)commandLine.getOptionValue("session-timeout"));

if (commandLine.getOptionValue("target-ip") == null) {

throw new IllegalStateException("as.sh is too old to support web console, " +

"please run the following command to upgrade to latest version:" +

"\ncurl -sLk https://alibaba.github.io/arthas/install.sh | sh");

}

configure.setIp((String) commandLine.getOptionValue("target-ip"));

configure.setTelnetPort((Integer) commandLine.getOptionValue("telnet-port"));

configure.setHttpPort((Integer) commandLine.getOptionValue("http-port"));

return configure;

}


private void attachAgent(Configure configure) throws Exception {

VirtualMachineDescriptor virtualMachineDescriptor = null;

for (VirtualMachineDescriptor descriptor : VirtualMachine.list()) {

String pid = descriptor.id();

if (pid.equals(Integer.toString(configure.getJavaPid()))) {

virtualMachineDescriptor = descriptor;

}

}

VirtualMachine virtualMachine = null;

try {

if (null == virtualMachineDescriptor) { // 使用 attach(String pid) 这种方式

virtualMachine = VirtualMachine.attach("" + configure.getJavaPid());

} else {

virtualMachine = VirtualMachine.attach(virtualMachineDescriptor);

}


Properties targetSystemProperties = virtualMachine.getSystemProperties();

String targetJavaVersion = JavaVersionUtils.javaVersionStr(targetSystemProperties);

String currentJavaVersion = JavaVersionUtils.javaVersionStr();

if (targetJavaVersion != null && currentJavaVersion != null) {

if (!targetJavaVersion.equals(currentJavaVersion)) {

AnsiLog.warn("Current VM java version: {} do not match target VM java version: {}, attach may fail.",

currentJavaVersion, targetJavaVersion);

AnsiLog.warn("Target VM JAVA_HOME is {}, arthas-boot JAVA_HOME is {}, try to set the same JAVA_HOME.",

targetSystemProperties.getProperty("java.home"), System.getProperty("java.home"));

}

}


String arthasAgentPath = configure.getArthasAgent();

//convert jar path to unicode string

configure.setArthasAgent(encodeArg(arthasAgentPath));

configure.setArthasCore(encodeArg(configure.getArthasCore()));

virtualMachine.loadAgent(arthasAgentPath,

configure.getArthasCore() + ";" + configure.toString());

} finally {

if (null != virtualMachine) {

virtualMachine.detach();

}

}

}


private static String encodeArg(String arg) {

try {

return URLEncoder.encode(arg, "utf-8");

} catch (UnsupportedEncodingException e) {

return arg;

}

}


public static void main(String[] args) {

try {

new Arthas(args);

} catch (Throwable t) {

AnsiLog.error("Start arthas failed, exception stack trace: ");

t.printStackTrace();

System.exit(-1);

}

}

}

那么  VirtualMachine.attach() 方法主要干了什么事情呢?

JVM Attach机制用途

  • 内存dump

  • 线程dump

  • 类信息统计(比如加载的类及大小以及实例个数等)

  • 动态加载agent(使用过btrace的应该不陌生)

  • 动态设置vm flag(但是并不是所有的flag都可以设置的，因为有些flag是在jvm启动过程中使用的，是一次性的)

  • 打印vm flag

  • 获取系统属性等

The Attach API is a Sun Microsystems extension that provides a mechanism to attach to a Java™ virtual machine. A tool written in the Java Language, uses this API to attach to a target virtual machine and load its tool agent into that virtual machine. For example, a management console might have a management agent which it uses to obtain management information from instrumented objects in a virtual machine. If the management console is required to manage an application that is running in a virtual machine that does not include the management agent, then this API can be used to attach to the target virtual machine and load the agent.

JVM Attach机制实现参考:

https://blog.csdn.net/huaweitman/article/details/50601602

Attach机制是什么？说简单点就是jvm提供一种jvm进程间通信的能力，能让一个进程传命令给另外一个进程，并让它执行内部的一些操作，比如说我们为了让另外一个jvm进程把线程dump出来，那么我们跑了一个jstack的进程，然后传了个pid的参数，告诉它要哪个进程进行线程dump，既然是两个进程，那肯定涉及到进程间通信，以及传输协议的定义，比如要执行什么操作，传了什么参数等

Attach能做些什么

总结起来说，比如内存dump，线程dump，类信息统计(比如加载的类及大小以及实例个数等)，动态加载agent(使用过btrace的应该不陌生)，动态设置vm flag(但是并不是所有的flag都可以设置的，因为有些flag是在jvm启动过程中使用的，是一次性的)，打印vm flag，获取系统属性等，这些对应的源码(AttachListener.cpp)如下

后面是命令对应的处理函数。

Attach在jvm里如何实现的

Attach Listener线程的创建

前面也提到了，jvm在启动过程中可能并没有启动Attach Listener这个线程，可以通过jvm参数来启动，代码 （Threads::create_vm）如下：

其中DisableAttachMechanism，StartAttachListener ，ReduceSignalUsage均默认是false(globals.hpp)

因此AttachListener::init()并不会被执行，而Attach Listener线程正是在此方法里创建的

既然在启动的时候不会创建这个线程，那么我们在上面看到的那个线程是怎么创建的呢，这个就要关注另外一个线程“Signal Dispatcher”了，顾名思义是处理信号的，这个线程是在jvm启动的时候就会创建的，具体代码就不说了。

下面以jstack的实现来说明触发Attach这一机制进行的过程，jstack命令的实现其实是一个叫做JStack.java的类，查看jstack代码后会走到下面的方法里

请注意VirtualMachine.Attach(pid);这行代码，触发Attach pid的关键，如果是在linux下会走到下面的构造函数

这里要解释下代码了，首先看到调用了createAttachFile方法在目标进程的cwd目录下创建了一个文件/proc//cwd/.Attach_pid，这个在后面的信号处理过程中会取出来做判断(为了安全)，另外我们知道在linux下线程是用进程实现的，在jvm启动过程中会创建很多线程，比如我们上面的信号线程，也就是会看到很多的pid(应该是LWP)，那么如何找到这个信号处理线程呢，从上面实现来看是找到我们传进去的pid的父进程，然后给它的所有子进程都发送一个SIGQUIT信号，而jvm里除了信号线程，其他线程都设置了对此信号的屏蔽，因此收不到该信号，于是该信号就传给了“Signal Dispatcher”，在传完之后作轮询等待看目标进程是否创建了某个文件，AttachTimeout默认超时时间是5000ms，可通过设置系统变量sun.tools.Attach.AttachTimeout来指定，下面是Signal Dispatcher线程的entry实现

当信号是SIGBREAK(在jvm里做了#define，其实就是SIGQUIT)的时候，就会触发

AttachListener::is_init_trigger()的执行，

一开始会判断当前进程目录下是否有个.Attach_pid文件（前面提到了），如果没有就会在/tmp下创建一个/tmp/.Attach_pid，当那个文件的uid和自己的uid是一致的情况下（为了安全）再调用init方法

此时水落石出了，看到创建了一个线程，并且取名为Attach Listener。再看看其子类LinuxAttachListener的init方法

看到其创建了一个监听套接字，并创建了一个文件/tmp/.java_pid，这个文件就是客户端之前一直在轮询等待的文件，随着这个文件的生成，意味着Attach的过程圆满结束了。

Attach listener接收请求

看看它的entry实现Attach_listener_thread_entry

从代码来看就是从队列里不断取AttachOperation，然后找到请求命令对应的方法进行执行，比如我们一开始说的jstack命令，找到 { “threaddump”, thread_dump }的映射关系，然后执行thread_dump方法

再来看看其要调用的AttachListener::dequeue()，

最终调用的是LinuxAttachListener::dequeue()，

我们看到如果没有请求的话，会一直accept在那里，当来了请求，然后就会创建一个套接字，并读取数据，构建出LinuxAttachOperation返回并执行。

整个过程就这样了，从Attach线程创建到接收请求，处理请求。


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK