介绍
关于java进程占用cpu问题，一般都是想知道
- 哪个(些)线程使用了更多的cpu
- 哪个(些)方法使用了更多的cpu
本文给出一个非常简要的介绍并给出了各个方法的使用例子，更深入使用可参考相关文档。 我觉得这些方法简单实用，已经帮助我解决过几次问题(产品环境过慢，性能调优)，希望对你也有帮助。
简要总结
| 目标 | 解决方式 | 说明 | 适用于 |
|---|---|---|---|
| 哪个(些)线程占用了很多的cpu | Step 1. 通过ps命令得到jvm的各个线程的cpu使用率（并排序) Step 2. 通过jstack的输出，找到这个线程(Step1中各个线程都有线程号) 注意：Step1(ps)中线程号为10进制，Step2(jstack)中为16进制。人肉转换的话，可以使用在线工具 http://www.binaryhexconverter.com/hex-to-decimal-converter， 或者 printf "%x\n" decimalNumber 来获得16进制 |
本方法非常实用，而且被讨论过很多次（如,杨彪 一次线上游戏卡死的解决历程 2017， http://www.boxjar.com/using-top-and-jstack-to-find-the-java-thread-that-is-hogging-the-cpu/ 2013）。建议直接使用现成脚本(譬如：https://github.com/robertleepeak/wizard-scripts/blob/master/show-busiest-java-threads 知名架构师李艳鹏的github）. 本方法非常适用于生产环境出现的cpu使用过高导致程序缓慢的问题。 下面的例子中也提供了一个可以直接复制/粘贴使用的例子。 |
产品环境 开发/测试环境 |
| 哪个(些)方法占用了很多的cpu - via jvisualvm | visualvm连接java 进程后 1. 点击Sample 标签 2. 开始你的测试，然后马上点击cpu按钮 3. cpu占用测试结束后，点击 Stop 4. 点击Snapshot暂存结果 5. 观察分析Snapshot结果 6. Snapshot结果可以保存 |
下面例子中，提供了截屏。使用方式比较简单直接。 另外：visualvm还支持使用类似的方式查看内存在检测期间的分配情况 |
ONLY 开发/测试环境 因为一般不允许通过visualvm连接产品环境。 |
| 哪个(些)方法占用了很多的cpu - via hprof | 官方链接(java8) | 添加-agentlib:hprof=cpu=samples到你的java进程启动脚本中，开始测试。测试结束后，关闭java进程。java进程退出后，在当前目录形成一个文件java.hprof.txt。这个文件中，包含了cpu使用方法排名。 本文会提供一个例子输出供参考。 该输出并没有visualvm信息丰富、直观。只有在visualvm无法使用，或者必须background执行的时候，才推荐使用。 |
None 平时工作中，我几乎从来没用使用这种方法。因为开发环境中，visualvm更合适。生产环境中，hprof是不会被使用的。 这里列出来只是提供一个新的思路。 |
note: https://www.tablesgenerator.com/markdown_tables# could help to generate markdown table
note: for newline in markdown table, you have to input
特别例子 - 线程 thread.sleep, or readBytes from console，但是仍然CPU很高
E.g. High CPU while read lines from console: http://www.jianshu.com/p/4a6fe6c82311
E.g. 微信群中，有人提出在一台测试Tomcat(没有任何load)，但是cpu仍使用了9%左右。通过jstack发现cpu最高的线程stack为Thread.sleep
此类问题相对来说更复杂一些，因为我们已经找到了相关的繁忙代码，但是这类代码不应该造成cpu繁忙。如read from console应该永远都不到，因为没有人输入; 如 thread.sleep不应该造成high cpu。
这里我给出一个思路
- 使用jvisualvm继续看一下，能否找到繁忙method的具体情况。可能在这一步就找到了问题根本原因
- 查看相关源代码
如：read lines from console这个例子，通过查看源代码可知，我们不期望从console读到任何东西，那么为什么读到了？读到了什么值? 可以通过重新编译源代码或者btrace注入的方式，看一下到底读到的什么值，进一步查看。那篇文章中，作者直接在console read之后，加入了一个sleep，简单粗暴的解决了这个问题。其实也没啥问题。
如：tomcat sleep的例子，通过检查源代码，
at java.lang.Thread.sleep(NativeMethod)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java: 1355)
at java.lang.Thread.run(Thread.java:748)
如果真正的在sleep，cpu肯定不会高。我怀疑下面的backgroundProcessorDelay值有问题。
while (!threadDone) {
try {
Thread.sleep(backgroundProcessorDelay * 1000L);
} catch (InterruptedException e) {
// Ignore
}
if (!threadDone) {
processChildren(ContainerBase.this);
}
}
这个可以通过btrace注入Thread.sleep方法，查看它到底调用的值是多少。
例子：查看哪个线程最繁忙（下面脚本可以直接复制粘贴到你的linux shell中)
直接复制下面的几行，就可以得到高cpu的那些线程,以及一个完整的jstack输出文件
process_id=YOUR_PROCESS_ID_TO_BE_REPLACED
tmp_jstack_file=/tmp/$(date '+%Y%m%d_%H%M%S')_$USER_$$_${process_id}_jstack_$RANDOM
jstack ${process_id} > $tmp_jstack_file
ps -Leo pid,lwp,user,comm,pcpu --no-headers| grep "^[[:space:]]\+${process_id}[[:space:]]\+" | sort -k5 -r -n | head -n"${top_count:-5}" | while read thread_line
do
threadId=$(echo ${thread_line} | awk '{print $2}')
threadId0x=$(printf %x ${threadId})
java_thread_info=$(grep "[[:space:]]nid=0x${threadId0x}[[:space:]]" ${tmp_jstack_file})
echo ${thread_line} ${java_thread_info}
done
echo "pid lwp user comm pcpu java_thread_info <- above columns"
echo "see full jstack info here: $tmp_jstack_file"
这是我的一个例子输出
wby@BaoyingUbuntu:~$ process_id=1702
wby@BaoyingUbuntu:~$ ps -Leo pid,lwp,user,comm,pcpu --no-headers| grep "^[[:space:]]\+${process_id}[[:space:]]\+" | sort -k5 -r -n | head -n"${top_count:-5}" | while read thread_line
> do
> threadId=$(echo ${thread_line} | awk '{print $2}')
> threadId0x=$(printf %x ${threadId})
> java_thread_info=$(grep "[[:space:]]nid=0x${threadId0x}[[:space:]]" ${tmp_jstack_file})
> echo ${thread_line} ${java_thread_info}
> done
1702 1709 wby java 1.0 "HPROF cpu sampling thread" #6 daemon prio=10 os_prio=0 tid=0x00007fdb70123800 nid=0x6ad runnable [0x0000000000000000]
1702 1704 wby java 1.0 "VM Thread" os_prio=0 tid=0x00007fdb700b1800 nid=0x6a8 runnable
1702 1756 wby java 0.0 "Attach Listener" #14 daemon prio=9 os_prio=0 tid=0x00007fdb48002000 nid=0x6dc waiting on condition [0x0000000000000000]
1702 1716 wby java 0.0 "VM Periodic Task Thread" os_prio=0 tid=0x00007fdb70247000 nid=0x6b4 waiting on condition
1702 1715 wby java 0.0 "RMI TCP Accept-0" #13 daemon prio=5 os_prio=0 tid=0x00007fdb70241800 nid=0x6b3 runnable [0x00007fdb5e0f6000]
wby@BaoyingUbuntu:~$ echo "pid lwp user comm pcpu java_thread_info <- above columns"
pid lwp user comm pcpu java_thread_info <- above columns
wby@BaoyingUbuntu:~$ echo "see full jstack info here: $tmp_jstack_file"
see full jstack info here: /tmp/20171023_084044_1678_1702_jstack_1280
在上面例子输出中，我们可以看到"HPROF cpu sampling thread"占用了最多的cpu(1.0)
1702 1709 wby java 1.0 "HPROF cpu sampling thread" #6 daemon prio=10 os_prio=0 tid=0x00007fdb70123800 nid=0x6ad runnable [0x0000000000000000]
例子：通过visualvm定位各个方法占用cpu时间
你可以同本地电脑的visualvm（JDK_HOME/bin/jvisualvm.exe)，连接查看远程服务器上java进程的情况(cpu, thread, memory, 等）。这里将举例介绍如何通过visualvm查看java进程的各个方法使用的cpu情况
如果是本地的java进程，那么启动visualvm之后，可以直接从左侧的Local列表中找到。
如果是远程的java进程，请确保远程进程打开了相关的端口如
-Dcom.sun.management.jmxremote.port=3333 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.rmi.server.hostname=远端服务器ip
然后添加JMX链接 - 远端服务器ip：远端端口 (即3333， 如果-Dcom.sun.management.jmxremote.port=3333）
cpu_jvisualvm.simple.png
接下来的截图，通过sample更多的package，得到更丰富的结果。
cpu_jvisualvm.setup.profile.package.png
cpu_jvisualvm.setup.profile.package.output.png
例子：通过hprof定位各个方法占用cpu时间
java -cp ../classes -agentlib:hprof=cpu=samples baoying.memory.HeapEater
hprof支持更多的功能和参数，详见官方链接(java8)
平时工作中，我几乎从来没用使用这种方法。因为开发环境中，visualvm更合适。生产环境中，hprof是不会被使用的。
这里列出来只是提供一个新的思路。
--------
THREAD START (obj=50000437, id = 200004, name="RMI TCP Accept-0", group="system")
THREAD START (obj=50000437, id = 200005, name="RMI TCP Accept-3333", group="system")
THREAD START (obj=50000437, id = 200006, name="RMI TCP Accept-0", group="system")
THREAD START (obj=50000437, id = 200001, name="main", group="main")
THREAD START (obj=50000437, id = 200008, name="SIGINT handler", group="system")
THREAD START (obj=50000513, id = 200009, name="Thread-0", group="main")
THREAD END (id = 200009)
THREAD END (id = 200008)
THREAD END (id = 200002)
TRACE 300509:
java.net.PlainSocketImpl.socketAccept(PlainSocketImpl.java:Unknown line)
java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
java.net.ServerSocket.implAccept(ServerSocket.java:545)
java.net.ServerSocket.accept(ServerSocket.java:513)
TRACE 300665:
java.io.FileInputStream.readBytes(FileInputStream.java:Unknown line)
java.io.FileInputStream.read(FileInputStream.java:255)
sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
TRACE 300667:
java.util.IdentityHashMap.keySet(IdentityHashMap.java:968)
java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:97)
java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
java.lang.Shutdown.runHooks(Shutdown.java:123)
TRACE 300022:
java.lang.Class.forName0(Class.java:Unknown line)
java.lang.Class.forName(Class.java:348)
sun.nio.cs.FastCharsetProvider.lookup(FastCharsetProvider.java:118)
sun.nio.cs.FastCharsetProvider.charsetForName(FastCharsetProvider.java:133)
TRACE 300048:
java.lang.Runtime.addShutdownHook(Runtime.java:211)
java.util.logging.LogManager.<init>(LogManager.java:258)
java.util.logging.LogManager.<init>(LogManager.java:251)
java.util.logging.LogManager$1.run(LogManager.java:204)
TRACE 300084:
java.lang.System.checkKey(System.java:840)
java.lang.System.getProperty(System.java:714)
com.sun.jmx.mbeanserver.GetPropertyAction.run(GetPropertyAction.java:44)
com.sun.jmx.mbeanserver.GetPropertyAction.run(GetPropertyAction.java:36)
TRACE 300118:
java.util.logging.LogManager$LoggerContext.getOwner(LogManager.java:646)
java.util.logging.LogManager$LoggerContext.requiresDefaultLoggers(LogManager.java:639)
java.util.logging.LogManager$LoggerContext.ensureDefaultLogger(LogManager.java:731)
java.util.logging.LogManager$LoggerContext.ensureInitialized(LogManager.java:683)
TRACE 300192:
java.lang.Class.isPrimitive(Class.java:Unknown line)
javax.management.openmbean.ArrayType.getPrimitiveArrayType(ArrayType.java:869)
com.sun.jmx.mbeanserver.DefaultMXBeanMappingFactory.<clinit>(DefaultMXBeanMappingFactory.java:223)
com.sun.jmx.mbeanserver.MXBeanMappingFactory.<clinit>(MXBeanMappingFactory.java:102)
TRACE 300214:
com.sun.jmx.mbeanserver.PerInterface$InitMaps.visitOperation(PerInterface.java:253)
com.sun.jmx.mbeanserver.MBeanAnalyzer.visit(MBeanAnalyzer.java:74)
com.sun.jmx.mbeanserver.PerInterface.<init>(PerInterface.java:54)
com.sun.jmx.mbeanserver.MBeanIntrospector.getPerInterface(MBeanIntrospector.java:195)
TRACE 300253:
java.lang.StringBuilder.append(StringBuilder.java:202)
sun.reflect.generics.parser.SignatureParser.parseIdentifier(SignatureParser.java:268)
sun.reflect.generics.parser.SignatureParser.parsePackageNameAndSimpleClassTypeSignature(SignatureParser.java:336)
sun.reflect.generics.parser.SignatureParser.parseClassTypeSignature(SignatureParser.java:310)
TRACE 300268:
sun.management.MemoryImpl.getMemoryPools0(MemoryImpl.java:Unknown line)
sun.management.MemoryImpl.getMemoryPools(MemoryImpl.java:92)
sun.management.ManagementFactoryHelper.getMemoryPoolMXBeans(ManagementFactoryHelper.java:112)
java.lang.management.PlatformComponent$6.getMXBeans(PlatformComponent.java:144)
TRACE 300278:
java.lang.String.startsWith(String.java:1434)
com.sun.jmx.mbeanserver.MXBeanIntrospector.getMBeanAttributeInfo(MXBeanIntrospector.java:149)
com.sun.jmx.mbeanserver.MXBeanIntrospector.getMBeanAttributeInfo(MXBeanIntrospector.java:54)
com.sun.jmx.mbeanserver.MBeanIntrospector$MBeanInfoMaker.visitAttribute(MBeanIntrospector.java:324)
TRACE 300282:
java.util.TreeMap$EntrySet.<init>(TreeMap.java:1061)
java.util.TreeMap.entrySet(TreeMap.java:889)
javax.management.ImmutableDescriptor.<init>(ImmutableDescriptor.java:107)
javax.management.ImmutableDescriptor.<init>(ImmutableDescriptor.java:74)
TRACE 300302:
java.lang.String.<init>(String.java:207)
java.lang.StringBuilder.toString(StringBuilder.java:407)
sun.management.DiagnosticCommandImpl.transform(DiagnosticCommandImpl.java:256)
sun.management.DiagnosticCommandImpl.getMBeanInfo(DiagnosticCommandImpl.java:172)
TRACE 300310:
java.util.Hashtable.get(Hashtable.java:362)
java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:693)
java.util.logging.LogManager.getLogger(LogManager.java:1226)
java.util.logging.LogManager.demandLogger(LogManager.java:551)
TRACE 300343:
java.io.BufferedReader.readLine(BufferedReader.java:313)
java.io.BufferedReader.readLine(BufferedReader.java:389)
sun.misc.MetaIndex.registerDirectory(MetaIndex.java:183)
sun.misc.Launcher$BootClassPathHolder$1.run(Launcher.java:401)
TRACE 300392:
java.lang.Double.toString(Double.java:204)
java.lang.String.valueOf(String.java:3141)
java.security.Provider.putId(Provider.java:688)
java.security.Provider.<init>(Provider.java:138)
TRACE 300417:
sun.security.provider.SecureRandom.init(SecureRandom.java:102)
sun.security.provider.SecureRandom.<init>(SecureRandom.java:79)
sun.security.provider.NativePRNG$RandomIO.getMixRandom(NativePRNG.java:387)
sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:483)
TRACE 300464:
sun.rmi.transport.DGCImpl$2.run(DGCImpl.java:295)
sun.rmi.transport.DGCImpl$2.run(DGCImpl.java:281)
java.security.AccessController.doPrivileged(AccessController.java:Unknown line)
sun.rmi.transport.DGCImpl.<clinit>(DGCImpl.java:281)
TRACE 300508:
sun.misc.PerfCounter$CoreCounters.<clinit>(PerfCounter.java:131)
sun.misc.PerfCounter.getParentDelegationTime(PerfCounter.java:167)
java.lang.ClassLoader.loadClass(ClassLoader.java:427)
java.lang.ClassLoader.loadClass(ClassLoader.java:357)
TRACE 300548:
sun.reflect.ByteVectorImpl.add(ByteVectorImpl.java:62)
sun.reflect.ClassFileAssembler.emitByte(ClassFileAssembler.java:74)
sun.reflect.ClassFileAssembler.emitConstantPoolNameAndType(ClassFileAssembler.java:119)
sun.reflect.AccessorGenerator.emitBoxingContantPoolEntries(AccessorGenerator.java:359)
TRACE 300605:
java.util.concurrent.ConcurrentHashMap.tabAt(ConcurrentHashMap.java:755)
java.util.concurrent.ConcurrentHashMap.transfer(ConcurrentHashMap.java:2421)
java.util.concurrent.ConcurrentHashMap.addCount(ConcurrentHashMap.java:2288)
java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1070)
TRACE 300638:
sun.management.ConnectorAddressLink.exportRemote(ConnectorAddressLink.java:140)
sun.management.jmxremote.ConnectorBootstrap.startRemoteConnectorServer(ConnectorBootstrap.java:479)
sun.management.Agent.startAgent(Agent.java:257)
sun.management.Agent.startAgent(Agent.java:447)
TRACE 300669:
java.util.logging.LogManager$LoggerContext.requiresDefaultLoggers(LogManager.java:637)
java.util.logging.LogManager$LoggerContext.ensureDefaultLogger(LogManager.java:731)
java.util.logging.LogManager$LoggerContext.ensureInitialized(LogManager.java:684)
java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:692)
CPU SAMPLES BEGIN (total = 814) Sun Oct 22 15:35:36 2017
rank self accum count trace method
1 72.97% 72.97% 594 300509 java.net.PlainSocketImpl.socketAccept
2 24.08% 97.05% 196 300665 java.io.FileInputStream.readBytes
3 0.37% 97.42% 3 300667 java.util.IdentityHashMap.keySet
4 0.12% 97.54% 1 300022 java.lang.Class.forName0
5 0.12% 97.67% 1 300048 java.lang.Runtime.addShutdownHook
6 0.12% 97.79% 1 300084 java.lang.System.checkKey
7 0.12% 97.91% 1 300118 java.util.logging.LogManager$LoggerContext.getOwner
8 0.12% 98.03% 1 300192 java.lang.Class.isPrimitive
9 0.12% 98.16% 1 300214 com.sun.jmx.mbeanserver.PerInterface$InitMaps.visitOperation
10 0.12% 98.28% 1 300253 java.lang.StringBuilder.append
11 0.12% 98.40% 1 300268 sun.management.MemoryImpl.getMemoryPools0
12 0.12% 98.53% 1 300278 java.lang.String.startsWith
13 0.12% 98.65% 1 300282 java.util.TreeMap$EntrySet.<init>
14 0.12% 98.77% 1 300302 java.lang.String.<init>
15 0.12% 98.89% 1 300310 java.util.Hashtable.get
16 0.12% 99.02% 1 300343 java.io.BufferedReader.readLine
17 0.12% 99.14% 1 300392 java.lang.Double.toString
18 0.12% 99.26% 1 300417 sun.security.provider.SecureRandom.init
19 0.12% 99.39% 1 300464 sun.rmi.transport.DGCImpl$2.run
20 0.12% 99.51% 1 300508 sun.misc.PerfCounter$CoreCounters.<clinit>
21 0.12% 99.63% 1 300548 sun.reflect.ByteVectorImpl.add
22 0.12% 99.75% 1 300605 java.util.concurrent.ConcurrentHashMap.tabAt
23 0.12% 99.88% 1 300638 sun.management.ConnectorAddressLink.exportRemote
24 0.12% 100.00% 1 300669 java.util.logging.LogManager$LoggerContext.requiresDefaultLoggers
CPU SAMPLES END
