使用jdk常用工具排查故障流程

基本流程

jps定位进程
jstat统计堆信息
jstack定位问题线程
jmap定位问题对象

jps

jps用于查看服务器当前有哪些java进程,排查问题时,一般先使用jps定位到pid
-l参数可以打印完整类路径或jar包路径,-v参数可以打印启动参数
备注: ps -ef | grep java 可以打印启动参数和jar路径,但打印不了类路径

sh-4.2
# jps -l
1 /home/adms_app.jar
2098 sun.tools.jps.Jps


jstat

jstat用于统计堆各区域的使用情况等信息

下图中,jstat -gc 1 1000 5命令表示每1000ms打印一次pid为1的进程的堆的信息,共打印5次。
S0C表示S0的capacity,即总容量,S0U表示S0的used,即已使用空间,单位为kb,U/C可以得到使用率,如MU/MC = 元空间使用率。
E、O、M分别表示Eden区、老年代、元空间,YGC/YGCT表示YGC的GC次数/GC时间,FGC/FGCT表示FGC的GC次数/GC时间。

sh-4.2# jstat -gc 1 1000 5
 S0C    S1C      S0U    S1U      EC       EU        OC         OU       MC       MU      CCSC     CCSU     YGC     YGCT    FGC    FGCT     GCT
68096.0 68096.0  0.0   17619.1 545344.0 31013.4  5609920.0  1641632.2  108988.0 106255.3 12508.0 11906.6     67    9.386   6      0.228    9.615
68096.0 68096.0  0.0   17619.1 545344.0 31015.5  5609920.0  1641632.2  108988.0 106255.3 12508.0 11906.6     67    9.386   6      0.228    9.615
68096.0 68096.0  0.0   17619.1 545344.0 31153.6  5609920.0  1641632.2  108988.0 106255.3 12508.0 11906.6     67    9.386   6      0.228    9.615
68096.0 68096.0  0.0   17619.1 545344.0 31181.7  5609920.0  1641632.2  108988.0 106255.3 12508.0 11906.6     67    9.386   6      0.228    9.615
68096.0 68096.0  0.0   17619.1 545344.0 31181.7  5609920.0  1641632.2  108988.0 106255.3 12508.0 11906.6     67    9.386   6      0.228    9.615
sh-4.2# jstat -gcutil 1 1000 5
 S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
 0.00  25.87  11.57  29.26  97.49  95.19     67    9.386     6    0.228    9.615
 0.00  25.87  11.57  29.26  97.49  95.19     67    9.386     6    0.228    9.615
 0.00  25.87  11.57  29.26  97.49  95.19     67    9.386     6    0.228    9.615
 0.00  25.87  11.69  29.26  97.49  95.19     67    9.386     6    0.228    9.615
 0.00  25.87  11.69  29.26  97.49  95.19     67    9.386     6    0.228    9.615

-gc参数显示具体数值,-gcutil展示比例


jstack

jstack用于查看某个进程内的线程信息,常用于排查cpu问题

使用jstack时,一般步骤如下
步骤1,用top -Hp pid查看pid进程内的线程的cpu占比,按cpu使用率从大到小排序。
本步骤需要着重观察的是: cpu占比较高的线程,以及cpu运行时间(即TIME+列)较长的线程

topHp.png

这里有一个问题,cpu多高算高?
假设有一个4核的cpu,一个核跑满是100%,整个cpu最高跑到400%。
如果有一个线程死循环(while true),cpu一般能到90%+,到不了100%是因为即使是while true,还是会有时间片轮转。

另外,cpu运行时间也是一个很重要的指标,上图中,pid为71的线程,跑了2小时18分钟,肯定有问题。

步骤2,把当前线程信息导出thread dump文件

sh-4.2# jstack -l 1 > 1.tdump

步骤3,根据上一步找到的问题线程的pid,把pid转成16进制,因为thread dump文件中,线程pid是用16进制表示的

sh-4.2# printf "%x\n" 71
47

步骤4,在thread dump文件中检索上一步算出的线程pid的16进制,一般看后20行,能看到完整调用栈即可

sh-4.2# grep 0x47 1.tdump -A20
"KafkaConsumerExample" #51 prio=5 os_prio=0 tid=0x00007f87d4539800 nid=0x47 runnable [0x00007f86cfcfd000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <0x00000000c29af7f0> (a sun.nio.ch.Util$2)
        - locked <0x00000000c29af808> (a java.util.Collections$UnmodifiableSet)
        - locked <0x00000000c297fbe8> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at org.apache.kafka.common.network.Selector.select(Selector.java:700)
        at org.apache.kafka.common.network.Selector.poll(Selector.java:422)
        at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:460)
        at org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(ConsumerNetworkClient.java:261)
        at org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(ConsumerNetworkClient.java:233)
        at org.apache.kafka.clients.consumer.KafkaConsumer.pollOnce(KafkaConsumer.java:1172)
        at org.apache.kafka.clients.consumer.KafkaConsumer.poll(KafkaConsumer.java:1116)
        at com.xxx.service.HkKafkaConsumer.doWork(HkKafkaConsumer.java:107)
        at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:82)

可以看到,该线程是kafka消费者线程

注意: 开发时,线程名一定要定好,能对应具体业务,这样用jstack的时候,可以根据线程名马上定位到具体业务。

另外,Thread类的getAllStackTraces方法可以获取当前虚拟机所有线程的调用栈,如果开发人员不方便上生产,可以用该api暴露接口。


jmap

jmap用于查看某个进程的对象信息,常用于排查内存问题

jmap -dump:live,format=b,file=/root/1.hprof 1把堆的内容打印到文件,live参数表示只输出活的对象。
备注:
heap dump文件的大小与当前堆使用量的大小一致,假如堆使用量为2G,heap dump文件就有2G,导出heap dump文件需要很长的时间,导出过程可能会影响对外服务。
另外,heap dump文件只有用专业的工具(如jhat、jvisualvm、mat)才能看,无法用grep等命令检索。
综上,一般很少在生产环境使用该命令。

sh-4.2# jmap -dump:live,format=b,file=/root/1.hprof 1
Dumping heap to /root/1.hprof ...
Heap dump file created

jmap -histo:live pid统计类实例数以及字节数。
一般用jmap -histo:live pid | grep packge检查是否内存泄漏,page为java项目的包名

sh-4.2# jmap -histo:live 1 | head -n 10

 num     #instances         #bytes  class name
----------------------------------------------
   1:        285471       28159520  [C
   2:        109772        9659936  java.lang.reflect.Method
   3:          9392        8411512  [B
   4:        283248        6797952  java.lang.String
   5:         78183        5158160  [Ljava.lang.Object;
   6:        145353        4651296  java.util.concurrent.ConcurrentHashMap$Node
   7:         93898        3755920  java.util.LinkedHashMap$Entry

jmap -J-D64 -heap 1打印heap的概要信息

sh-4.2#  jmap -J-D64 -heap 1
Attaching to process ID 1, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.73-b02

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 6442450944 (6144.0MB)
   NewSize                  = 697892864 (665.5625MB)
   MaxNewSize               = 697892864 (665.5625MB)
   OldSize                  = 5744558080 (5478.4375MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 628162560 (599.0625MB)
   used     = 292043832 (278.5147018432617MB)
   free     = 336118728 (320.5477981567383MB)
   46.491760349422925% used
Eden Space:
   capacity = 558432256 (532.5625MB)
   used     = 272566632 (259.9397964477539MB)
   free     = 285865624 (272.6227035522461MB)
   48.80925646243472% used
From Space:
   capacity = 69730304 (66.5MB)
   used     = 19477200 (18.574905395507812MB)
   free     = 50253104 (47.92509460449219MB)
   27.932188564673403% used
To Space:
   capacity = 69730304 (66.5MB)
   used     = 0 (0.0MB)
   free     = 69730304 (66.5MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 5744558080 (5478.4375MB)
   used     = 1681031336 (1603.1564102172852MB)
   free     = 4063526744 (3875.281089782715MB)
   29.263022718015588% used

51598 interned Strings occupying 5488888 bytes.


总结

按上面的步骤,一般可以定位到问题,但是比较困难,需要在短时间内做大量操作,因此,推荐使用阿里的arthas

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 159,716评论 4 364
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 67,558评论 1 294
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 109,431评论 0 244
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 44,127评论 0 209
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,511评论 3 287
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,692评论 1 222
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,915评论 2 313
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,664评论 0 202
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,412评论 1 246
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,616评论 2 245
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,105评论 1 260
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,424评论 2 254
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,098评论 3 238
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,096评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,869评论 0 197
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,748评论 2 276
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,641评论 2 271

推荐阅读更多精彩内容