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("任务结束运行");  

}}

 

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

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

 

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

业务场景是比分直播。

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

页面访问 伪代码类似:

 @RequestMapping("/getLiveData")

@ResponseBody

public String getLiveData(String lotteryCode) {    

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

String result = getDataFromMemcache(lotteryCode);    

 return result; }

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

 

2 jstack分析 

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

执行命令类似: 

jstack -l pid >> statck.txt

 

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

kill  -3  pid

堆栈格式： 

"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

dump格式说明： 

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

 public enum State {        

NEW,        

RUNNABLE,        

BLOCKED,        

WAITING,      

 TIMED_WAITING,        

TERMINATED;    

}

在线程转换图： 

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

 

来找到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    

 

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

解决方式也比较简单 : 

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