java profile cpu_Java进程高CPU使用调查方法简介

介绍

关于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进制

产品环境

开发/测试环境

哪个(些)方法占用了很多的cpu - via jvisualvm

visualvm连接java 进程后

1. 点击Sample 标签

2. 开始你的测试，然后马上点击cpu按钮

3. cpu占用测试结束后，点击 Stop

4. 点击Snapshot暂存结果

5. 观察分析Snapshot结果

6. Snapshot结果可以保存

下面例子中，提供了截屏。使用方式比较简单直接。

另外：visualvm还支持使用类似的方式查看内存在检测期间的分配情况

ONLY 开发/测试环境

因为一般不允许通过visualvm连接产品环境。

哪个(些)方法占用了很多的cpu - via hprof

添加-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

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

pid lwp user comm pcpu java_thread_info

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.(LogManager.java:258)

java.util.logging.LogManager.(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.(DefaultMXBeanMappingFactory.java:223)

com.sun.jmx.mbeanserver.MXBeanMappingFactory.(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.(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.(TreeMap.java:1061)

java.util.TreeMap.entrySet(TreeMap.java:889)

javax.management.ImmutableDescriptor.(ImmutableDescriptor.java:107)

javax.management.ImmutableDescriptor.(ImmutableDescriptor.java:74)

TRACE 300302:

java.lang.String.(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.(Provider.java:138)

TRACE 300417:

sun.security.provider.SecureRandom.init(SecureRandom.java:102)

sun.security.provider.SecureRandom.(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.(DGCImpl.java:281)

TRACE 300508:

sun.misc.PerfCounter$CoreCounters.(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.

14 0.12% 98.77% 1 300302 java.lang.String.

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.

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