Thread命令
cpu占比是如何统计出来的?
Thread用法
Arthas
是Alibaba开源的Java诊断工具,深受开发者喜爱。在线排查问题,无需重启;动态跟踪Java代码;实时监控JVM状态。
Arthas
支持JDK 6+,支持Linux/Mac/Windows,采用命令行交互模式,同时提供丰富的 Tab
自动补全功能,进一步方便进行问题的定位和诊断。
当你遇到以下类似问题而束手无策时,Arthas可以帮助你解决:
这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
是否有一个全局视角来查看系统的运行状况?
有什么办法可以监控到JVM的实时运行状态?
怎么快速定位应用的热点,生成火焰图?
本教程会以一个简单的应用为例,演示thread命令。
Github: https://github.com/alibaba/arthas
文档: https://arthas.aliyun.com/doc/
下载arthas-demo.jar
,再用java -jar
命令启动:
bash wget https://arthas.aliyun.com/arthas-demo.jar;java -jar arthas-demo.jar
arthas-demo
是一个很简单的程序,它随机生成整数,再执行因式分解,把结果打印出来。如果生成的随机数是负数,则会打印提示信息。
在新的Terminal 2
里,下载arthas-boot.jar
,再用java -jar
命令启动:
bash wget https://arthas.aliyun.com/arthas-boot.jar;java -jar arthas-boot.jar
arthas-boot
是Arthas
的启动程序,它启动后,会列出所有的Java进程,用户可以选择需要诊断的目标进程。
选择第一个进程,输入 1
,再Enter/回车
:
bash 1
Attach成功之后,会打印Arthas LOGO。输入 help
可以获取到更多的帮助信息。
bash help
查看当前线程信息,查看线程的堆栈
| 参数名称 | 参数说明 | | -------- | ------------------------------------- | | id | 线程id | | [n:] | 指定最忙的前N个线程并打印堆栈 | | [b] | 找出当前阻塞其他线程的线程 | | [i ] | 指定cpu占比统计的采样间隔,单位为毫秒 | | [–all] | 显示所有匹配的线程 |
这里的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这个脚本
Thread用法
bash thread -n 3 console $ thread -n 3 "C1 CompilerThread0" [Internal] cpuUsage=1.63% deltaTime=3ms time=1170ms "arthas-command-execute" Id=23 cpuUsage=0.11% deltaTime=0ms time=401ms RUNNABLE at java.management@11.0.7/sun.management.ThreadImpl.dumpThreads0(Native Method) at java.management@11.0.7/sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:466) at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:199) at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108) at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385) at java.base@11.0.7/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base@11.0.7/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base@11.0.7/java.lang.Thread.run(Thread.java:834) "VM Periodic Task Thread" [Internal] cpuUsage=0.07% deltaTime=0ms time=584ms
没有线程ID,包含[Internal]
表示为JVM内部线程,参考dashboard
命令的介绍。
cpuUsage
为采样间隔时间内线程的CPU使用率,与dashboard
命令的数据一致。
deltaTime
为采样间隔时间内线程的增量CPU时间,小于1ms时被取整显示为0ms。
time
线程运行总CPU时间。
注意:线程栈为第二采样结束时获取,不能表明采样间隔时间内该线程都是在处理相同的任务。建议间隔时间不要太长,可能间隔时间越大越不准确。 可以根据具体情况尝试指定不同的间隔时间,观察输出结果。
默认按照CPU增量时间降序排列,只显示第一页数据,避免滚屏。
bash thread console $ thread Threads Total: 33, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0, Internal threads: 17 ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON -1 C2 CompilerThread0 - -1 - 5.06 0.010 0:0.973 false true -1 C1 CompilerThread0 - -1 - 0.95 0.001 0:0.603 false true 23 arthas-command-execute system 5 RUNNABLE 0.17 0.000 0:0.226 false true -1 VM Periodic Task Thread - -1 - 0.05 0.000 0:0.094 false true -1 Sweeper thread - -1 - 0.04 0.000 0:0.011 false true -1 G1 Young RemSet Sampling - -1 - 0.02 0.000 0:0.025 false true 12 Attach Listener system 9 RUNNABLE 0.0 0.000 0:0.022 false true 11 Common-Cleaner InnocuousThrea 8 TIMED_WAI 0.0 0.000 0:0.000 false true 3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true 2 Reference Handler system 10 RUNNABLE 0.0 0.000 0:0.000 false true 4 Signal Dispatcher system 9 RUNNABLE 0.0 0.000 0:0.000 false true 15 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.029 false true 22 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.196 false true 24 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.038 false true 16 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true 17 arthas-NettyWebsocketTtyBootst system 5 RUNNABLE 0.0 0.000 0:0.001 false true
显示所有匹配线程信息,有时需要获取全部JVM的线程数据进行分析。
bash thread --all
查看线程ID 16的栈:
bash thread 16 console $ 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)
有时候我们发现应用卡住了, 通常是由于某个线程拿住了某个锁, 并且其他线程都在等待这把锁造成的。 为了排查这类问题, arthas提供了thread -b
, 一键找出那个罪魁祸首。
bash thread -b console $ 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 1000
: 统计最近1000ms内的线程CPU时间。
bash thread -i 1000
thread -n 3 -i 1000
: 列出1000ms内最忙的3个线程栈
bash thread -n 3 -i 1000 console $ 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 ...
bash thread --state WAITING console [arthas@28114]$ thread --state WAITING Threads Total: 16, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0 ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON 3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true 20 arthas-UserStat system 9 WAITING 0.0 0.000 0:0.001 false true 14 arthas-timer system 9 WAITING 0.0 0.000 0:0.000 false true
在“thread”中,我们演示了了Arthas的thread命令。如果有更多的技巧或者使用疑问,欢迎在Issue里提出。
Issues: https://github.com/alibaba/arthas/issues
文档: https://arthas.aliyun.com/doc
如果您在使用Arthas,请让我们知道。您的使用对我们非常重要:查看
文章拷贝来源:https://start.aliyun.com/course?spm=a2ck6.17690074.0.0.28bc2e7dHTphXs&id=PaiFAkJM