利用线程Dump来查找高消耗CPU代码

Posted on | In | |

对于CPU消耗高的代码，可以用下面的方法来进行定位分析。

前提

运行一段Java代码，让它消耗CPU。

定位

  1. 用top查找出高消耗CPU PID

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    [root@Automation logs]# top
    top - 10:14:33 up 19:47,  4 users,  load average: 0.48, 0.41, 0.32
    Tasks: 189 total,   1 running, 188 sleeping,   0 stopped,   0 zombie
    Cpu(s): 11.8%us, 15.0%sy,  0.0%ni, 70.4%id,  0.0%wa,  1.4%hi,  1.4%si,  0.0%st
    Mem:   3389932k total,  3284936k used,   104996k free,   182736k buffers
    Swap:  3522556k total,    11740k used,  3510816k free,  1144964k cached

      PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                                                                                         
    14538 root      20   0 1916m  52m  10m S 30.8  1.6   8:33.55 java                                                                                                                                                                                                             
    14087 root      20   0  100m 4688 3504 S 16.3  0.1  14:21.79 sshd                                                                                                                                                                                                             
    10032 root      20   0 1125m 277m  49m S  4.0  8.4  99:02.94 firefox

  2. 用top -p <PID>查找出线程ID - (输入H查看所有线程的统计信息)

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    [root@Automation logs]# top -p 14538
    top - 10:21:53 up 19:54,  4 users,  load average: 0.48, 0.44, 0.35
    Tasks:   3 total,   0 running,   3 sleeping,   0 stopped,   0 zombie
    Cpu(s): 11.9%us, 15.8%sy,  0.0%ni, 69.9%id,  0.0%wa,  0.9%hi,  1.6%si,  0.0%st
    Mem:   3389932k total,  3243372k used,   146560k free,   182704k buffers
    Swap:  3522556k total,    12700k used,  3509856k free,  1105400k cached

      PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                                                                                         
    14539 root      20   0 1916m  52m  10m S 33.0  1.6  10:53.38 java                                                                                                                                                                                                             
    14540 root      20   0 1916m  52m  10m S 25.6  1.6   0:00.77 java                                                                                                                                                                                                             
    14538 root      20   0 1916m  52m  10m S  0.0  1.6   0:00.00 java

  3. 用jstack <PID>做线程Dump

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    54
    55
    56
    57
    58
    59
    60
    61
    62
    63
    64
    65
    66
    67
    [root@Automation logs]# jstack 14538
    2018-06-20 10:18:12
    Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.80-b11 mixed mode):

    "Attach Listener" daemon prio=10 tid=0x00007f6cbc001000 nid=0x38fe waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE

    "Service Thread" daemon prio=10 tid=0x00007f6ce8093000 nid=0x38d4 runnable [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE

    "C2 CompilerThread1" daemon prio=10 tid=0x00007f6ce8090800 nid=0x38d3 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE

    "C2 CompilerThread0" daemon prio=10 tid=0x00007f6ce808d800 nid=0x38d2 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE

    "Signal Dispatcher" daemon prio=10 tid=0x00007f6ce808b000 nid=0x38d1 runnable [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE

    "Finalizer" daemon prio=10 tid=0x00007f6ce806a800 nid=0x38d0 in Object.wait() [0x00007f6cd7efd000]
       java.lang.Thread.State: WAITING (on object monitor)
    	at java.lang.Object.wait(Native Method)
    	- waiting on <0x00000000cc4028c0> (a java.lang.ref.ReferenceQueue$Lock)
    	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
    	- locked <0x00000000cc4028c0> (a java.lang.ref.ReferenceQueue$Lock)
    	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
    	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

    "Reference Handler" daemon prio=10 tid=0x00007f6ce8068800 nid=0x38cf in Object.wait() [0x00007f6cd7ffe000]
       java.lang.Thread.State: WAITING (on object monitor)
    	at java.lang.Object.wait(Native Method)
    	- waiting on <0x00000000cc4025c0> (a java.lang.ref.Reference$Lock)
    	at java.lang.Object.wait(Object.java:503)
    	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
    	- locked <0x00000000cc4025c0> (a java.lang.ref.Reference$Lock)

    "main" prio=10 tid=0x00007f6ce8008800 nid=0x38cb runnable [0x00007f6ceec18000]
       java.lang.Thread.State: RUNNABLE
    	at java.io.FileOutputStream.writeBytes(Native Method)
    	at java.io.FileOutputStream.write(FileOutputStream.java:345)
    	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    	- locked <0x00000000cc405728> (a java.io.BufferedOutputStream)
    	at java.io.PrintStream.write(PrintStream.java:482)
    	- locked <0x00000000cc405708> (a java.io.PrintStream)
    	at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    	at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
    	at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
    	- locked <0x00000000cc405800> (a java.io.OutputStreamWriter)
    	at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
    	at java.io.PrintStream.write(PrintStream.java:527)
    	- locked <0x00000000cc405708> (a java.io.PrintStream)
    	at java.io.PrintStream.print(PrintStream.java:597)
    	at java.io.PrintStream.println(PrintStream.java:736)
    	- locked <0x00000000cc405708> (a java.io.PrintStream)
    	at TestA.testA(TestA.java:10)
    	at TestA.main(TestA.java:3)

    "VM Thread" prio=10 tid=0x00007f6ce8064000 nid=0x38ce runnable 

    "GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f6ce801e000 nid=0x38cc runnable 

    "GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f6ce8020000 nid=0x38cd runnable 

    "VM Periodic Task Thread" prio=10 tid=0x00007f6ce809e000 nid=0x38d5 waiting on condition 

    JNI global references: 138

  4. 转换（十进制 - 十六进制）nid

    1
    14539 --> 38cb

  5. 在Dump中查找相应nid

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    "main" prio=10 tid=0x00007f6ce8008800 nid=0x38cb runnable [0x00007f6ceec18000]
       java.lang.Thread.State: RUNNABLE
    	at java.io.FileOutputStream.writeBytes(Native Method)
    	at java.io.FileOutputStream.write(FileOutputStream.java:345)
    	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    	- locked <0x00000000cc405728> (a java.io.BufferedOutputStream)
    	at java.io.PrintStream.write(PrintStream.java:482)
    	- locked <0x00000000cc405708> (a java.io.PrintStream)
    	at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    	at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
    	at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
    	- locked <0x00000000cc405800> (a java.io.OutputStreamWriter)
    	at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
    	at java.io.PrintStream.write(PrintStream.java:527)
    	- locked <0x00000000cc405708> (a java.io.PrintStream)
    	at java.io.PrintStream.print(PrintStream.java:597)
    	at java.io.PrintStream.println(PrintStream.java:736)
    	- locked <0x00000000cc405708> (a java.io.PrintStream)
    	at TestA.testA(TestA.java:10)
    	at TestA.main(TestA.java:3)

基本上一定位一个准。

唐胡璐 wechat
欢迎您扫一扫上面的微信公众号，订阅我的博客！
分享创造价值，您的支持将鼓励我继续前行！