jstack那些事（一）

前言

工作多年，经常遇到灵异事件，比如说: "任务为什么不跑了" , "没什么复杂业务呀，怎么cpu这么高" ,"用了缓存，怎么查询还是这么慢" , 一些工作一两年的同学遇到这类问题可能会手足无措 ，所以我想写一些文字来和大家分享下 。文笔有限，主要是交流。 这篇是先和大家交流 jstack的用法，以及编程方面的一些建议。 

1 经典场景

 • 场景一 ：任务（线程）突然不跑了

程序是一段简单的quartz 任务 ，伪代码类似:

public class DataJobs

{   public void run() {  

 log.info("任务开始运行");  

 //准备数据    

Object prepareData = prepare();  

 //调用http远程接口获取    

Result result = getHttpRemoteData(prepareData);

   //存储    store(result);  

 log.info("任务结束运行");  

}}
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.

查看日志可用查看到 “任务开始运行”   但后续没有打印“任务结束运行” 

业务也没有正常处理 , 也没有异常  无奈之下 只好重启服务 

 • 场景二 cpu load 特别高  业务也不复杂  
如下图:

业务场景是比分直播。

页面的逻辑是每隔几秒从memached 获取实时比赛信息 ，根据彩种类别获取数据，然后前端渲染。

页面访问 伪代码类似:

 @RequestMapping("/getLiveData")

@ResponseBody

public String getLiveData(String lotteryCode) {    

//从memcache中获取比分直播数据  仅仅是一个 get key from memcahed    

String result = getDataFromMemcache(lotteryCode);    

 return result; }
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.

异常问题：页面非常卡顿 ，服务器上 cpu 利用率 和 load 非常高 。

2 jstack分析 

jstack是jdk自带的线程堆栈分析工具，使用该命令可以查看或导出 Java 应用程序中线程堆栈信息。

执行命令类似: 

jstack -l pid >> statck.txt
1.

有时 也可以采用 kill -3 命令 实现打印堆栈的效果 

kill  -3  pid
1.

堆栈格式： 

"redisson-netty-2-4" #37 prio=5 os_prio=0 tid=0x00007f91ae738000 nid=0x3bf1 runnable [0x00007f91a5b4d000]

 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:93)      

at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)      

- locked <0x00000000ee106580> (a io.netty.channel.nio.SelectedSelectionKeySet)    

 - locked <0x00000000ee1065b0> (a java.util.Collections$UnmodifiableSet)    

 - locked <0x00000000edff8448> (a sun.nio.ch.EPollSelectorImpl)      

at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)    

 at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)    

 at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:752)      

at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:408)    

at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)      

at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)      

at java.lang.Thread.run(Thread.java:748)
   Locked ownable synchronizers:        

- None
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.

dump格式说明： 

在jstack输出的第二行为线程的状态，在JVM中线程状态使用枚举 java.lang.Thread.State 来表示，State的定义如下：

 public enum State {        

NEW,        

RUNNABLE,        

BLOCKED,        

WAITING,      

 TIMED_WAITING,        

TERMINATED;    

}
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.

在线程转换图： 

jstack关键字分析

3 解决问题

   3.1 线程阻塞问题  

    回到场景一  依靠上面的命令 我们打印出模拟的jstack堆栈 

"Quartz-2" #1 prio=5 os_prio=31 tid=0x00007feb6c008000 nid=0x2603 runnable [0x000070000771a000]   java.lang.Thread.State: RUNNABLE  

at java.net.SocketInputStream.socketRead0(Native Method)  at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)  

at java.net.SocketInputStream.read(SocketInputStream.java:170)  at java.net.SocketInputStream.read(SocketInputStream.java:141)  

at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)  at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)

 at java.io.BufferedInputStream.read(BufferedInputStream.java:345)  - locked <0x00000007959e1830> (a java.io.BufferedInputStream)  

at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:704)  at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:647)  

at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1535)  - locked <0x00000007959b1848> (a sun.net.www.protocol.http.HttpURLConnection)  

at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1440)  - locked <0x00000007959b1848> (a sun.net.www.protocol.http.HttpURLConnection)  

at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2942)  

at java.net.URLConnection.getContentType(URLConnection.java:512)

 at com.courage.platform.sms.client.util.SmsHttpClientUtils.getResponseAsString(SmsHttpClientUtils.java:345)

 at com.courage.platform.sms.client.util.SmsHttpClientUtils.doGet(SmsHttpClientUtils.java:241)

由上可见，当前线程阻塞在从http链接中获取响应数据。 可能对方httpserver耗时长，或者对方server hang住了 。针对这种情况，我适当的调整了 http client 的 connect 和read timeout。

   3.2 cpu高问题

回到场景二，

我们先用ps命令找到对应进程的pid(如果你有好几个目标进程，可以先用top看一下哪个占用比较高)。
接着用

top -H -p pid
1.

来找到cpu使用率比较高的一些线程 （下图是模拟图）

然后将占用最高的pid转换为16进制printf '%x\n' pid得到nid

接着直接在jstack中找到相应的堆栈信息jstack pid | grep  'nid'  -C5  –color

 可以看到我们已经找到了nid为0x42的堆栈信息。

比分直播 我们查询到占用cpu最高的是 GC 线程。那我们怀疑是由于GC 频率过高导致的。

然后使用 jstat 每隔1s查看内存使用情况

jstat -gcutil pid 1000    
1.

发现新生代每隔两秒就基本占满了  ,  然后查看每个key对应的数据大小，发现每个value大小是500k左右 。   

解决方式也比较简单 : 

 ○减少缓存数据大小 
 ○适当调整新生代的大小
 ○首次查询全量， 后续通过websocket推送增量给前端