jstack工具解析及案例

命令描述

jstack:用来查看指定java进程的jvm线程栈信息

使用方法

jstack -[operation] pid
其中operation：
-F:当 jstack pid没有响应时，使用-F强制dump线程信息
-m:打印java线程栈和本地线程栈
-l:长期监听，打印锁信息

结果描述

使用jstack pid dump出来的线程信息如下：

"pool-24-thread-85" #22861 prio=5 os_prio=0 tid=0x00007fdae45fc800 nid=0x2bba waiting on condition [0x00007fd94ca8a000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000070f27ab40> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"Ice.ThreadPool.Client-252" #22835 daemon prio=5 os_prio=0 tid=0x00007fda5804b800 nid=0x2769 runnable [0x00007fd9504fc000]
   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:79)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x000000070ba2ae50> (a sun.nio.ch.Util$2)
    - locked <0x000000070ba2ae68> (a java.util.Collections$UnmodifiableSet)
    - locked <0x000000070b3193f0> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at IceInternal.Selector.select(Selector.java:258)
    at IceInternal.ThreadPool.run(ThreadPool.java:319)
    at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
    at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:643)
    at java.lang.Thread.run(Thread.java:745)

其中包含线程基本信息和线程栈信息，从平时暴露的问题来看主要关注的在两个方面
（1）线程中的死锁情况：deadlock
（2）栈中调用的方法情况，尤其当发现大部分的线程栈在调用某个特定方法的时候，这个方法基本可以确定是有问题的

案例

这个案例来自公司日常开发运维中遇到的问题，感谢亲爱的同事们的分析和帮助！

开发过程中没有遇到过通过线程栈排查死锁问题，但是排查慢接口的问题遇到过几次。

首先讲一下现象：

某天客服小妹反馈线上服务不可用了，好捉急

问题排查

1. 看下邮件，是否有报警。因为我们是web服务，如果端口挂了或者有特别的多5XX都会收到报警邮件-false
2. 访问下线上服务，确认务是不是真的不可用了 -true
3. 登录到一台线上服务器，看下线上日志，是不是有报错。-false（因为这边是分布式部署，当时访问的服务器确实没有问题）
4. 然后赶紧打开其他的服务器日志，忽然发现日志根本没在动，ps一下进程，发现进程没了！没了！
5. netstat一下端口，发现端口还在。但是状态都是TIME_WAIT
   
6. 重启挂掉的服务
7. 重启后使用jstack查看线程栈信息：
   
   从线程栈信息可以看到栈里面执行cacheManager.getResource()和exists()方法特别多，基本可以定位问题在这里。
8. 于是去对应的方法里面看了一下，并没有看出什么端倪。此处只是获取redis连接， 而exists也只是执行了一下redis的exists方法。但是这个文件确实当天被改动并上线过。

 public Jedis getResource() {
        Jedis jedis = null;
        try {
            jedis = jedisPool.getResource();
        } catch (Exception e) {
            LOGGER.error("Failed to get jedis resource, reason is " + e.getMessage());
        }
        return jedis;
    }

1. CacheManager这个文件从之前手动初始化单例的方式，换成了用spring管理，并用注解注入。最开始怀疑是初试化方式不对，有可能在不断的创建redis连接，因为创建连接的部分写在后遭方法里面，但是尝试了几次发现，这个都早方法并不会调用多次。

        public CacheManager() {
        JedisPoolConfig config = new JedisPoolConfig();
        AppConfigs appConfigs = AppConfigs.getInstance();
        config.setMinIdle(Integer.parseInt(appConfigs.get(KEY_POOL_MIN_IDLE)));
        config.setMaxIdle(Integer.parseInt(appConfigs.get(KEY_POOL_MAX_IDLE)));
        this.jedisPool = new JedisPool(config,
                appConfigs.get(KEY_SERVER_HOST),
                Integer.parseInt(appConfigs.get(KEY_SERVER_PORT)));
    }

1. 然后对比了一下修改前后的文件发现了这样的两处代码：

   修改前的代码：

修改后的代码：

这样修改后redis连接不被回收！导致连接发生瞬时暴增。

总结

redis连接瞬时暴增后getResource()方法超时严重，请求得不到释放。服务器端tomcat的最大线程数配置是 maxThreads=1000（默认200），队列中允许的请求数是：acceptCount=500（默认10）。导致几乎所有的请求都阻塞在getResource()上，tomcat处理能力达到了极限。由于我们所有的服务都通过nginx代理，最终新进来的请求会被nginx直接返回而不能到达tomcat端，浏览器端显示502。

至于服务进程为什么没了，我想是因为这个服务过于消耗资源被操作系统kill了。