2022-07-15 22:37:32 +08:00
# thread
2018-09-07 16:16:05 +08:00
2020-08-07 18:28:00 +08:00
[`thread`在线教程 ](https://arthas.aliyun.com/doc/arthas-tutorials.html?language=cn&id=command-thread )
2020-07-23 22:32:23 +08:00
2022-07-15 22:37:32 +08:00
::: tip
查看当前线程信息,查看线程的堆栈
:::
2018-09-07 16:16:05 +08:00
2022-08-09 18:42:39 +08:00
## 参数说明
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
| 参数名称 | 参数说明 |
| ------------: | :------------------------------------------------------ |
| _id_ | 线程 id |
| [n:] | 指定最忙的前 N 个线程并打印堆栈 |
| [b] | 找出当前阻塞其他线程的线程 |
| [i `<value>` ] | 指定 cpu 使用率统计的采样间隔,单位为毫秒,默认值为 200 |
| [--all] | 显示所有匹配的线程 |
2018-09-07 16:16:05 +08:00
2022-08-09 18:42:39 +08:00
## cpu 使用率是如何统计出来的?
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
这里的 cpu 使用率与 linux 命令`top -H -p < pid > ` 的线程`%CPU`类似,一段采样间隔时间内,当前 JVM 里各个线程的增量 cpu 时间与采样间隔时间的比例。
2020-09-22 22:18:51 +08:00
2022-08-09 18:42:39 +08:00
### 工作原理说明:
2020-09-22 22:18:51 +08:00
2022-07-15 22:37:32 +08:00
- 首先第一次采样,获取所有线程的 CPU 时间(调用的是`java.lang.management.ThreadMXBean#getThreadCpuTime()`及`sun.management.HotspotThreadMBean.getInternalThreadCpuTimes()`接口)
- 然后睡眠等待一个间隔时间(默认为 200ms, 可以通过`-i`指定间隔时间)
- 再次第二次采样,获取所有线程的 CPU 时间,对比两次采样数据,计算出每个线程的增量 CPU 时间
- 线程 CPU 使用率 = 线程增量 CPU 时间 / 采样间隔时间 \* 100%
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
::: warning
注意: 这个统计也会产生一定的开销( JDK 这个接口本身开销比较大),因此会看到 as 的线程占用一定的百分比,为了降低统计自身的开销带来的影响,可以把采样间隔拉长一些,比如 5000 毫秒。
:::
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
::: tip
另外一种查看 Java 进程的线程 cpu 使用率方法:可以使用[`show-busy-java-threads`](https://github.com/oldratlee/useful-scripts/blob/dev-2.x/docs/java.md#-show-busy-java-threads)这个脚本。
:::
2018-09-07 16:16:05 +08:00
2022-08-09 18:42:39 +08:00
## 使用参考
2018-09-07 16:16:05 +08:00
2022-08-09 18:42:39 +08:00
### 支持一键展示当前最忙的前 N 个线程并打印堆栈:
2018-09-07 16:16:05 +08:00
```shell
$ thread -n 3
2020-09-22 22:18:51 +08:00
"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
```
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
- 没有线程 ID, 包含`[Internal]`表示为 JVM 内部线程,参考[dashboard](dashboard.md)命令的介绍。
- `cpuUsage` 为采样间隔时间内线程的 CPU 使用率,与[dashboard](dashboard.md)命令的数据一致。
- `deltaTime` 为采样间隔时间内线程的增量 CPU 时间,小于 1ms 时被取整显示为 0ms。
- `time` 线程运行总 CPU 时间。
2018-09-07 16:16:05 +08:00
2020-09-22 22:18:51 +08:00
注意:线程栈为第二采样结束时获取,不能表明采样间隔时间内该线程都是在处理相同的任务。建议间隔时间不要太长,可能间隔时间越大越不准确。
可以根据具体情况尝试指定不同的间隔时间,观察输出结果。
2018-09-07 16:16:05 +08:00
2022-08-09 18:42:39 +08:00
### 当没有参数时,显示第一页线程的信息
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
默认按照 CPU 增量时间降序排列,只显示第一页数据。
2018-09-07 16:16:05 +08:00
```shell
$ thread
2020-09-22 22:18:51 +08:00
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
2018-09-07 16:16:05 +08:00
```
2022-08-09 18:42:39 +08:00
### thread --all, 显示所有匹配的线程
2020-09-22 22:18:51 +08:00
2022-07-15 22:37:32 +08:00
显示所有匹配线程信息,有时需要获取全部 JVM 的线程数据进行分析。
2020-09-22 22:18:51 +08:00
2022-08-09 18:42:39 +08:00
### thread id, 显示指定线程的运行堆栈
2018-09-07 16:16:05 +08:00
```shell
$ 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)
```
2022-08-09 18:42:39 +08:00
### thread -b, 找出当前阻塞其他线程的线程
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
有时候我们发现应用卡住了, 通常是由于某个线程拿住了某个锁, 并且其他线程都在等待这把锁造成的。 为了排查这类问题, arthas 提供了`thread -b`, 一键找出那个罪魁祸首。
2018-09-07 16:16:05 +08:00
2018-09-27 11:47:20 +08:00
```bash
2018-09-07 16:16:05 +08:00
$ 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
```
2022-07-15 22:37:32 +08:00
::: warning
注意, 目前只支持找出 synchronized 关键字阻塞住的线程, 如果是`java.util.concurrent.Lock`, 目前还不支持。
:::
2018-09-07 16:16:05 +08:00
2022-08-09 18:42:39 +08:00
### thread -i, 指定采样时间间隔
2018-09-07 16:16:05 +08:00
2022-07-15 22:37:32 +08:00
- `thread -i 1000` : 统计最近 1000ms 内的线程 CPU 时间。
- `thread -n 3 -i 1000` : 列出 1000ms 内最忙的 3 个线程栈
2020-09-22 22:18:51 +08:00
2018-09-27 11:47:20 +08:00
```bash
2018-09-07 16:16:05 +08:00
$ 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
...
2018-10-13 13:05:48 +08:00
```
2019-10-12 11:27:58 +08:00
2022-08-09 18:42:39 +08:00
### thread --state ,查看指定状态的线程
2019-10-12 11:27:58 +08:00
```bash
[arthas@28114]$ thread --state WAITING
2020-09-22 22:18:51 +08:00
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
2019-10-12 11:27:58 +08:00
```