资料内容讲稿jstack和java thread dumps分析

1、JStack 和 Java ThDumps 分析12JStack 和 Java ThDumps 分析任喜军Java 程序员总是非常幸运地有 Sun 公司给力的工具 jstack 帮你 Dump 当前所有 Java 线程的运行堆栈（jstack 工具在你的 JDK 安装目录的 bin/ 里面可以看到）Jstack 用法帮助jstack -help Usage:jstack -l (to connect to running process) jstack -F -m -l (to connect to a hung process) jstack -m -l (to connect to a c

2、ore file)jstack -m -l server_id (to connect to a remote debug server)Options:-F to force a thdump. Use when jstack does not respond (process is hung)-m to print both java and native frames (mixed mode)-l long listing. Prints additional information about locks-h or -help to print this help message其中

3、pid （Java 进程的 id 号，你可以通过 JDK/bin/jps 工具来获取你的机器上所有正在运行的 java 进程id）是必要的参数。-l：输出 locks 相关的。jstack l 2345 stack.log /表示将 java 进程号为 2345 的堆栈转存到文件 stack.log中。可以使用JDK 自带的工具：jps 来查看所有运行的Java 进程号jps 用法：$ jps -help usage: jps -helpjps -q -mlvV Definitions:接下来就是分析这个 stack.log 文件,帮你发现你的程序都在干什么、以及有哪些锁竞争激烈。查看锁竞争简

4、单案例，MyTh.java 的代码：1 public class MyThimplements Runnable 23 public void run() 4 synchronized(this) 5for (int i = 1; i 10000000; i-) 6System.out.println(Th.currentTh().getName() + synchronized loop + i);7if( i % 10000 = 0)8try9this.notifyAll();10this.wait(1000);11catch(Exception e)12e.printStackTrace

5、();131415161718public static void main(String args) 19MyTht1 = new MyTh();20Thta = new Th(t1, A);21Thtb = new Th(t1, B);22Thtc = new Th(t1, C);23ta.start();24tb.start();25tc.start();2627将这段代码运行起来，然后用 Jstack 命令不停地去抓取 Stack，就会得到这样的结果：16 C prio=10 tid=0x00007f342809d000 nid=0x2606 in Object.wait() 0x00

6、007f342e1a200017 java.lang.Th .State: TIMED_WAITING (on object monitor)18 at java.lang.Object.wait(Native Method)19- waiting on (a MyTh)20at MyTh.run(MyTh .java:10)21- locked (a MyTh)22at java.lang.Th.run(Th .java:679) 2324 B prio=10 tid=0x00007f342809b000 nid=0x2605 in Object.wait() 0x00007f342e2a3

7、00025 java.lang.Th .State: BLOCKED (on object monitor)26 at java.lang.Object.wait(Native Method)27- waiting on (a MyTh)28at MyTh.run(MyTh .java:10)29- locked (a MyTh)30at java.lang.Th.run(Th .java:679) 3132 A prio=10 tid=0x00007f3428099000 nid=0x2604 0x00007f342e3a400033 java.lang.Th .State: RUNNABL

8、Erunnable34 at java.io.FileOutputStream.writeBytes(Native Method)35 atjava.io.FileOutputStream.write(FileOutputStream.java:297)36 atjava.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)37 atjava.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) 38- locked (ajava.io.Buffer

9、edOutputStream)39 at java.io.PrintStream.write(PrintStream.java:449)40 - locked (a java.io.PrintStream)41 atsun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)42 atsun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)43 atsun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:103

10、) 44- locked (ajava.io.OutputStreamWriter)45 atjava.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)46 at java.io.PrintStream.newLine(PrintStream.java:513)47 - locked (a java.io.PrintStream)48 at java.io.PrintStream.println(PrintStream.java:774)49 - locked (a java.io.PrintStream)50 at

11、MyTh.run(MyTh .java:6)51- locked (a MyTh)52at java.lang.Th.run(Th .java:679)每一段都表示一个线程调用栈，如这一行：A prio=10 tid=0x00007f3428099000 nid=0x2604 runnable 0x00007f342e3a4000A ： 该线程名字，建议大家创建线程的时候给定一个名字，便于定位nid=0x2604： 该线程的线程号是 16 进制的 2604 runnable ： 该线程当前的状态，这个很重要接下来的这一行是对线程状态的详细说明：java.lang.Th.State: RUNNA

12、BLE这一个线程（线程号：2604）的调用栈从下往上读，从 atjava.lang.Th.run(Th.java:679) 开始调用 MyTh.java 的第 6 行：6System.out.println(Th.currentTh().getName() + synchr onized loop + i);说明该线程进入到了 synchronized 代码块里面，抢到了 this 这个锁。这也意味着所有其他线 得等待，没法执行 synchronized 代码块，也就是我们可以看到线程 A ：51- locked (a MyTh)线程 B :25java.lang.Th.State: BLOC

13、KED (on object monitor) 27- waiting on (a MyTh)线程 C ：17java.lang.Th.State: TIMED_WAITING (on object monitor) 19- waiting on (a MyTh)很明显线程 A 抢到了锁 0x00000000c2002180(this)同时线程 B/C 只能是BLOCKED 和 TIMED_WAITIN 状态。而这里的线程B 是 BLOCKED 状态，意味着线程B 尝试去获取 this 锁，但是没，所以被blocked 了；而线程 C 是 TIMED_WAITING 状态意味着线程C 是主动代

14、用第 10 行代码：10this.wait(1000);进入等待状态的，并且带有 1000ms 的 timeout 时间，也就是C 线 wait 1000ms 后将主动尝试获取 this 锁，也就是执行这行代码：4synchronized(this) 当然这个 1000ms 这中间没有其它线程调用第 9 行代码：9this.notifyAll();如果反复执行 jstack 去抓取线程状态的话会发现 A B C 三个线程状态这 RUNNABLE BLOCKED TIMED_WAITING 轮转，这也是我们这段代码的目的。通过 MyTh.java 这段简单的代码和线程调用栈来分析，我们得到了一些

15、基本的认识，让我们回到所有其它课本给我们讲解的这些东西：如果一个线程尝试通过 synchronized 去获取锁失败的话就会处于上图中红色的 Blocked 状态（如线程 B），一旦获取到锁后也就是上图中的 Entered monitor ，然后进入绿色的Runnable 状态（如线程 A），在 Runnable 过程中一旦执行了 Object.wait（不带timeout 参数）/LockSupport.part 就会进入上图中的橙色 Waiting 状态，如果执行的是Object.wait（带有 timeout 参数）/Th.sleep 就会进入橙色的 Timed Waiting 状态。当

16、有其他线程调用了 Object.notify/Object.notifyAll 后由橙色状态尝试进入Runnable 状态，当然能不能进入 Runnable 状态还得看能否抢到锁，抢不到的自然进入红色的Blocked 状态。下面这个图也可以帮我们加深对这个过程的理解：下面这个图中，左边的 Entry Set 就是表示所有处于 BLOCED 的线程（如果这些线程特别多说明锁竞争很严重）, 中间的 The Owner 表示拿到锁的线程处于 RUNNABLE， 最右边的 Wait Set 就是上面所分析的处于 WAITING/TIMED_WAITING 状态的所有线程通过 jstack 来定位 CP

17、U 消耗过高的地方下面再通过一个多线程对 HashMap 的并发写（put）来看看线程的状态，首先我们知道HashMap 不是线程安全的，意味着在不加锁的情况下，对 HashMap 并发写会导致问题，详细分析请看参考资料（酷壳： Java HashMap 的死循环），简单来说如果多线程并发地对同一个HashMap 执行 put 函数去向 HashMap 增加新元素的时候 HashMap 需要动态扩容，在扩容的过程中会导致 HashMap 的链表变成循环链表，一旦链表变成循环链表后再到 HashMap 取元素（get 的时候需要对链表进行遍历）就如陷入死循环。看代码 HashMapTh.java

18、:1 import java.util.HashMap; 23 public class HashMapThimplements Runnable 4 private static HashMap map = new HashMap();56public void run() 78String thName = Th .currentTh().getName();9for (int i = 1; i 10000000; i+) 10if(th Name.equals(A)11for(int j=1; ji-1; j+)12System.out.println(-+map.get(A + j);

19、13141516 map.put(thName + i, thName + i);17 System.out.println(map.get(thName + i);181920212223 public static void main(String args) 24 HashMapTh t1 = new HashMapTh();25 Thta = new Th(t1, A);26 Thtb = new Th(t1, B);27 Thtc = new Th(t1, C);28 ta.start();29 tb.start();30 tc.start();313233 这里 A B C 三个线

20、没有加锁的情况下同时对 HashMap 进行 put 操作，这个程序执行起来，进过很短暂的正常输出后，整个程序都停在那里了但是可以看到在 4 核的机器上三个线 满满地占用整个一个 CPU 核，也就是整个 CPU 占用率非常高但是程序没有任何输出，这是很不正常的。同样我们通过 jstack 来分析 HashMapTh这个程序，抓取到了这样的东西：37 C prio=10 tid=0x00007f427c01f000 nid=0x5d1e runnable 0x00007f42822e200038 java.lang.Th .State: RUNNABLE39 at java.util.HashM

21、ap.put(HashMap.java:391)40 at HashMapTh.run(HashMapTh.java:16)41 at java.lang.Th.run(Th.java:679) 4243 Locked ownable synchronizers:44 - None4546 B prio=10 tid=0x00007f427c01d000 nid=0x5d1d runnable 0x00007f42823e300047 java.lang.Th .State: RUNNABLE48 at java.util.HashMap.put(HashMap.java:391)49 at

22、HashMapTh.run(HashMapTh.java:16)50 at java.lang.Th.run(Th.java:679) 5152 Locked ownable synchronizers:53 - None5455 A prio=10 tid=0x00007f427c01b000 nid=0x5d1c runnable 0x00007f42824e400056 java.lang.Th .State: RUNNABLE57 at java.util.HashMap.put(HashMap.java:391)58 at HashMapTh.run(HashMapTh.java:1

23、6)59 at java.lang.Th.run(Th.java:679) 6061 Locked ownable synchronizers:62 - None这表示 A B C 三个线正在执行：at java.util.HashMap.put(HashMap.java:391)反复执行 jstack 多次后，每次看到的都是三个线在执行这行代码，让我们来看看HashMap.java 里面的第 391 行代码在干什么：# HashMap.java# 386public V put(K key, V value) # 387if (key = null)# 388return putForNul

24、lKey(value); # 389int hash = hash(key.hashCode();# 390int i = indexFor(hash, table.length);# 391for (Entry e = tablei; e != null; e = e.next) # 392Object k;# 393if (e.hash = hash & (k = e.key) = key | key.equals(k) #394V oldValue = e.value;#395e.value = value;#396e.recordAccess(this);#397return oldV

25、alue;#398#399#400#401modCount+;#402addEntry(hash, key, value,i);#403return null;#404果然在一个 for 循环中，这个 for 循环一直执行到 e = null 后才会停止，但是由于我们前面所分析的并 况下 HashMap 的链表有可能成为循环链表，也就是这个 for 循环永远 停止了，一个这样的线程就会干掉一整个 CPU 核，这也是 Hash 的原理（URL 中的参数会放入一个 HashMap）通过 jstack 来分析死锁来看一段简单会导致死锁的代码：1 public class DeadLockThimpl

26、ements Runnable23private Object monitor_A = new Object(); 45private Object monitor_B = new Object(); 67public void method_A()synchronized(monitor_B) 9synchronized(monitor_A) 810System.out.println(Th.currentTh().getName()+ invoke m ethod A);1112131415public void method_B()synchronized(monitor_A) 17sy

27、nchronized(monitor_B) 1618System.out.println(Th.currentTh().getName()+ invoke m ethod B);1920212223public void run() 24for(int i=0;i1;i-)25 method_A();26 method_B();27282930 public static void main(String args)31 DeadLockTh t1 = new DeadLockTh();32 Thta = new Th(t1, A);33 Thtb = new Th(t1, B); 3435

28、ta.start();36 tb.start(); 3738 这段代码很明显，函数 method_B 先去拿 monitor_B 的锁然后再拿 monitor_A 的锁，而函数 method_A 正好相反，如果两个线程不停地调用这两个函数的话总会碰到一个线程拿着monitor_A 同时等待拿 monitor_B，而另外一个线程正好相反拿着 monitor_B 等待拿monitor_A，这两个线程就陷入了死锁状态。这个时候运行这个程序，一小会后就没有输出了，然后通过 jstack 查看线程状态，得到了这样的东西：16 B prio=10 tid=0x00007f120401c800 nid=0x

29、5c54 waiting for monitor entry 0x00007f120b9e400017 java.lang.Th .State: BLOCKED (on object monitor)18 at DeadLockTh.method_B(DeadLockTh .java:18)19 - waiting to lock (a java.lang.Object)20 - locked (a java.lang.Object)21 at DeadLockTh.run(DeadLockTh .java:26)22 at java.lang.Th.run(Th .java:679) 232

30、4 Locked ownable synchronizers:25 - None2627 A prio=10 tid=0x00007f120401a800 nid=0x5c53 waiting for monitor entry 0x00007f120bae500028 java.lang.Th .State: BLOCKED (on object monitor)29 at DeadLockTh.method_A(DeadLockTh .java:10)30 - waiting to lock (a java.lang.Object)31 - locked (a java.lang.Obje

31、ct)32 at DeadLockTh.run(DeadLockTh .java:25)33 at java.lang.Th.run(Th .java:679) 3435 Locked ownable synchronizers:36 - None这个时候我们看到线程 A 拿着锁 0x00000000eb596140 ：31- locked (a java.lang.Object)同时在等待获取另外一个锁 0x00000000eb596150 ：30- waiting to lock (a java.lang.Object)而线程 B 正好相反，拿着锁 0x00000000eb596150 ：

32、20- locked (a java.lang.Object)同时等待获取另外一个锁 0x00000000eb596140 ：19- waiting to lock (a java.lang.Object)这样 A、B 两个线程就形成了典型的死锁。当然我们在 jstack 输出的最后面能发现这样的输出：109 Java stack information for the ths listed above: 110 = 111 B:112at DeadLockTh.method_B(DeadLockTh.java:18)113- waiting to lock (a java.lang.Obje

33、ct)114- locked (a java.lang.Object)115at DeadLockTh.run(DeadLockTh.java:26)116at java.lang.Th.run(Th.java:679)117 A:118at DeadLockTh.method_A(DeadLockTh.java:10)119- waiting to lock (a java.lang.Object)120- locked (a java.lang.Object)121at DeadLockTh.run(DeadLockTh.java:25)122at java.lang.Th.run(Th.

34、java:679)123124Found1 deadlock.也就是 jstack 自动帮我们识别出了这个死锁，并给出了详细的锁情况。jstack 在实际复杂案例中的应用案例 1 我曾经碰到过一个朋友倾诉说他们的服务器太慢了，但是又不知道服务器在忙什么，按着他的感觉觉得服务器没什么 ，但实际上看到 CPU 负载很高， 响应缓慢。通过jstack 拿到了输出，在这个中间我发现了 60 多个线在做类似这样的事情（*.# 是我隐藏了该公司的 ）：7 http-80-150 daemon prio=10 tid=0x00007fab5c10dc00 nid=0x5cba runnable 0x0000

35、7fab9b4cc000.0x00007fab9b4cf7908 java.lang.Th .State: RUNNABLE9 at java.util.ArrayList.indexOf(ArrayList.java:215)10 at java.util.ArrayList.contains(ArrayList.java:199)11 atjava.util.AbstractCollection.removeAll(AbstractCollection.java:336)12 at java_util_List$removeAll$1.call(Unknown Source)13 atco

36、m.*.#.service.game.GameMaskService.removePauseGame(GameMaskSe rvice.groovy:79)14 atcom.*.#.service.game.GameMaskService$removePauseGame$0.call(Unk nown Source)15 atcom.*.#.service.game.GameService.filterGameList(GameService.gro ovy:61)16 atcom.*.#.service.game.GameService$filterGameList.callCurrent(

37、Unk nown Source)17 atcom.*.#.service.game.GameService.getAdaptiveGameNames(GameServi ce.groovy:156)18 atcom.*.#.service.game.GameService$getAdaptiveGameNames.call(Unkn own Source)19 atcom.*.#.taglib.GameTagLib$_closure3.doCall(GameTagLib.groovy:88)20 atsun.reflect.GeneratedMethodAccessor1569.invoke(

38、Unknown Source)21 atsun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess orImpl.java:25)22 at java.lang.reflect.Method.invoke(Method.java:597)23 atorg.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:9 0)24 atgroovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233

39、)25 atgroovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1071)26 atgroovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:1110)27 atgroovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:901)28 at groovy.lang.Closure.call(Closure.java:415)由于我不了解该公司业务，但是从这个调用栈中大概能猜到估计是这个业务里面有一个所有游戏

40、的集合，然后每个用户登录、 页面的时候要在这里面去掉一些用户过滤的游戏（比如 所有停止运营的游戏， 希望这些游戏不要展示给该用户）。实现这个功能的时候程序员简单的将所有游戏放在一个 ArrayList A 中，然后将停止运营的游戏放在另外一个 ArrayList B 中， 每次用户登录、 游戏列表的时候都做一次 ArrayList. retainAll(Collection c) ，也就是从A 中将 B 中的所有游戏都删除掉。发现这个问题后该公司检查业务逻辑发现这个根本没必要，直接 一个游戏的白列表就完事了，一下子就将服务器负载降低了 80%！扩展开来看这个问题的话，如果要过滤的游戏列表每个用

41、户都可以 定义 不喜欢、不希望看到的游戏的话，那我们只需要在用户登录的时候计算一次得到该用的游戏白 就可以了，同时计算的时候也不能用 ArrayList,要用排序两个 List 去做差，这样计算效率从 N*M 的复杂段降低到了 N。案例 2一行未执行的 Log 导致性能下降了 4 倍某同学写了点很简单的新功能，然后上线了，然后悲剧了，发现整个系统的 Throughput 下降了 4 倍，并且该同学也反复检查了 提交的代码，非常简单，发现不了任何问题。这个时候我让该同学用 jstack 抓了几次 stack 给我，我分析了一下很快发现 stack 中有很多线是出于 BLOCKED 状态：1085

42、3 http--8080-13 daemon prio=10 tid=0x00000000578eb800 nid=0x2e91 waiting for monitor entry 0x000000006567600010854java.lang.Th .State: BLOCKED (on object monitor) 10855atcom.sun.xml.bind.v2.runtime.reflect.opt.Injector.inject(Injector.java: 174)10856- waiting to lock (a com.sun.xml.bind.v2.ru

43、ntime.reflect.opt.Injector) 10857atcom.sun.xml.bind.v2.runtime.reflect.opt.Injector.inject(Injector.java: 85)JStack 和 Java Th Dumps 分析10858atcom.sun.xml.bind.v2.runtime.reflect.opt.AccessorInjector.prepare(Acces sorInjector.java:87)10859atcom.sun.xml.bind.v2.runtime.reflect.opt.OptimizedTransducedAc

44、cessorFac tory.get(OptimizedTransducedAccessorFactory.java:137)10860atcom.sun.xml.bind.v2.runtime.reflect.TransducedAccessor.get(TransducedA ccessor.java:166)10861perty.AttributeProperty.(Attribut eProperty.java:87)10862perty.Property

45、Factory.create(PropertyFa ctory.java:104)10863atcom.sun.xml.bind.v2.runtime.ClassBeanInfoImpl.(ClassBeanInfoImpl.java:175) 10864atcom.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImp l.java:515)10865atcom.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImp l.java:534

46、)10866perty.ArrayElementProperty.(Array ElementProperty.java:108)10867perty.ArrayElementNodeProperty.(A rrayElementNodeProperty.java:58)10868atsun.reflect.GeneratedConstructorAccessor66.newInstance(Unknown Source) 10869atsun.reflect.D

47、elegatingConstructorAccessorImpl.newInstance(DelegatingCo nstructorAccessorImpl.java:27)10870atjava.lang.reflect.Constructor.newInstance(Constructor.java:513) 10871perty.PropertyFactory.create(PropertyFa ctory.java:124)10872atcom.sun.xml.bind.v2.runtime.ClassBeanInfo

48、Impl.(ClassBeanInfoImpl.java:175) 10873atcom.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImp l.java:515)10874atcom.sun.xml.bind.v2.runtime.JAXBContextImpl.(JAXBContextImpl.jav a:330)10875atcom.sun.xml.bind.v2.runtime.JAXBContextImpl$JAXBContextBuilder.build(J AXBContextImpl.java:1

49、136)13JStack 和 Java ThDumps 分析10876atcom.sun.xml.bind.v2.ContextFactory.createContext(ContextFactory.java:1 54)10877atcom.sun.xml.bind.v2.ContextFactory.createContext(ContextFactory.java:1 21)10878atsun.reflect.GeneratedMethodAccessor1228.invoke(Unknown Source) 10879atsun.reflect.DelegatingMethodAcc

50、essorImpl.invoke(DelegatingMethodAccess orImpl.java:25)10880at java.lang.reflect.Method.invoke(Method.java:597)10881atjavax.xml.bind.ContextFinder.newInstance(ContextFinder.java:211) 10882atjavax.xml.bind.ContextFinder.find(ContextFinder.java:372) 10883atjavax.xml.bind.JAXBContext.newInstance(JAXBCo

51、ntext.java:574) 10884atjavax.xml.bind.JAXBContext.newInstance(JAXBContext.java:522) 10885at*.#mon.ResourceCandidate.toXML(ResourceCandidate.java:74) 10886at*.#.erm.cache.facade.ERMServiceFacade.allocateResource_aroundBod y0(ERMServiceFacade.java:180)从上面的线程调用栈发现该线 等待锁在执行 ERMServiceFacade.java:180 行中的allocateResource 函数时需要获取锁 0x00000006bdab6428 ，同时我在搜索发现这个锁被下面这个线程拿到了：75492 http--8080-51 daemon prio=10 tid=0x00002aaac94cf000 nid=0x2eb7 runnable 0x0000000067c9c00075493java.lang.Th .State: RUNNABLE75494at java.lang.ClassLoader.defineClass1(