jstack那些事

勇哥java实战分享

发布于 2022-07-27 19:28:07

8700

发布于 2022-07-27 19:28:07

文章被收录于专栏：勇哥编程游记

前言

工作多年，经常遇到灵异事件，比如说: "任务为什么不跑了" , "没什么复杂业务呀，怎么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格式说明：

属性	说明
redisson-netty-2-4	线程名称
prio=5	该线程jvm中优先级 ‍
os_prio=0	该线程在os中的优先级 ‍
tid	该jvm内的thread id ‍
nid	Native thread id 本地操作系统相关 (高度依赖操作系统平台)

‍

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

 public enum State {
        NEW,
        RUNNABLE,
        BLOCKED,
        WAITING,
        TIMED_WAITING,
        TERMINATED;
    }

在线程转换图：

jstack关键字分析

关键字	说明
deadlock	死锁
waiting on condition	等待某个资源或条件发生来唤醒自己。具体需要结合jstacktrace来分析，比如线程正在sleep,网络读写繁忙而等待
Blocked	阻塞
waiting on monitor entry	等待获取锁 ‍
in Object.wait()	获取锁后又执行obj.wait()

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推送增量给前端

4 编码习惯引导

4.1 设置线程名

线程名设置主要是为了在jstack堆栈中便于查询。在logback日志中最好也标注下线程名。当遇到问题也有一个查询源。

线程名有如下两种方式:

手工设置线程名

Thread t = new Thread(new Runnable() {
     @Override
     public void run() {
       //something process 
      }
});
t.setName("mytestThread");
t.start();

线程工厂设置（源码来自rocketmq 4.4）

public class ThreadFactoryImpl implements ThreadFactory {
    private final AtomicLong threadIndex = new AtomicLong(0);
    private final String threadNamePrefix;
    private final boolean daemon;
    public ThreadFactoryImpl(final String threadNamePrefix) {
      this(threadNamePrefix, false);
    }
    public ThreadFactoryImpl(final String threadNamePrefix, boolean daemon) {
      this.threadNamePrefix = threadNamePrefix;
      this.daemon = daemon;
    }
    @Override
    public Thread newThread(Runnable r) {
     Thread thread = new Thread(r, threadNamePrefix + this.threadIndex.incrementAndGet());
      thread.setDaemon(daemon);
      return thread;
    }
}

使用方式：

this.traceExecutor = new ThreadPoolExecutor(
  10, 
  20, 
  1000 * 60, 
  TimeUnit.MILLISECONDS, 
  this.appenderQueue,
  new ThreadFactoryImpl("MQTraceSendThread_"));
traceProducer = getAndCreateTraceProducer(rpcHook);

4.2 线程池隔离

线程隔离主要有线程池隔离，在实际使用时我们会把请求分类，然后交给不同的线程池处理，当一种业务的请求处理发生问题时，不会将故障扩散到其他线程池，从而保证其他服务可用。

以开源代码rocketmq举例:

我们来看下broker启动时，发送消息 & pull 消息都是不同的线程池处理请求。

分为

发送消息线程池
pull消息线程池
查询消息线程池
回复消息线程池

代码如下:

//发送消息 处理器
this.remotingServer.registerProcessor(RequestCode.SEND_MESSAGE, sendProcessor, this.sendMessageExecutor);

//pull消息 处理器
this.remotingServer.registerProcessor(RequestCode.PULL_MESSAGE, this.pullMessageProcessor, this.pullMessageExecutor);
this.pullMessageProcessor.registerConsumeMessageHook(consumeMessageHookList);

//消费管理处理器
ConsumerManageProcessor consumerManageProcessor = new ConsumerManageProcessor(this);
this.remotingServer.registerProcessor(RequestCode.GET_CONSUMER_LIST_BY_GROUP, consumerManageProcessor, this.consumerManageExecutor);

//事务处理器
this.remotingServer.registerProcessor(RequestCode.END_TRANSACTION, new EndTransactionProcessor(this), this.endTransactionExecutor);
this.fastRemotingServer.registerProcessor(RequestCode.END_TRANSACTION, new EndTransactionProcessor(this), this.endTransactionExecutor);

4.3 超时设置

为了避免线程池大规模阻塞，合理的设置超时时间非常重要。常见超时有如下

http 读写超时（jdk httpurlconnection）

cononnection(new URL(n = getCurl), METHOD_POST, ctype);
fillHeaders(conn, headers);
conn.setConnectTimeout(connectTimeout);
conn.setReadTimeout(readTimeout);
out = conn.getOutputStream();

加锁时间(分布式场景下 redission)

RLock lock = redisson.getLock("myLock");
// traditional lock method
lock.lock();
// or acquire lock and automatically unlock it after 10 seconds
lock.lock(10, TimeUnit.SECONDS);
// or wait for lock aquisition up to 100 seconds 
// and automatically unlock it after 10 seconds
boolean res = lock.tryLock(100, 10, TimeUnit.SECONDS);
if (res) {
   try {
     ...
   } finally {
       lock.unlock();
   }
}

网络通讯（通过countdownlatch实现）

 public RemotingCommand invokeSyncImpl(final Channel channel, final RemotingCommand request,
        final long timeoutMillis)
   throws InterruptedException, RemotingSendRequestException, RemotingTimeoutException {
    final int opaque = request.getOpaque();
    try {
       final ResponseFuture responseFuture = new ResponseFuture(channel, opaque, timeoutMillis, null, null);
       this.responseTable.put(opaque, responseFuture);
       final SocketAddress addr = channel.remoteAddress();
       channel.writeAndFlush(request).addListener(new ChannelFutureListener() {
        @Override
        public void operationComplete(ChannelFuture f) throws Exception {
           if (f.isSuccess()) {
              responseFuture.setSendRequestOK(true);
             return;
          } else {
             responseFuture.setSendRequestOK(false);
          }
          responseTable.remove(opaque);
          responseFuture.setCause(f.cause());
          responseFuture.putResponse(null);
           log.warn("send a request command to channel <" + addr + "> failed.");
       }
     });
   RemotingCommand responseCommand =
       responseFuture.waitResponse(timeoutMillis);
       if (null == responseCommand) {
          if (responseFuture.isSendRequestOK()) {
            throw new RemotingTimeoutException(RemotingHelper.parseSocketAddressAddr(addr), timeoutMillis, responseFuture.getCause());
          } else {
            throw new RemotingSendRequestException(RemotingHelper.parseSocketAddressAddr(addr), responseFuture.getCause());
          }
        }
         return responseCommand;
    } finally {
        this.responseTable.remove(opaque);
     }
}

rocketmq封装了 responseFuture 对象超时设置通过countdown来实现超时效果

public RemotingCommand waitResponse(final long timeoutMillis) 
throws InterruptedException {
    this.countDownLatch.await(timeoutMillis, TimeUnit.MILLISECONDS);
    return this.responseCommand;
}

5 专业产品推荐

5.1. 阿里Arthas

Arthas 是Alibaba开源的Java诊断工具。我们从下图看到一个简单得命令就可以查看当进程阻塞的线程