p6spy打印sql日志线程不安全导致的生产问题

  首先说明下我这个标题可能起的不到位，其实我本次要介绍的是一次生产定位问题的思路及过程。

1.生产现象

   国庆前期发布了一个很小版本，大家都以为没什么问题，可是发布后生产出现了问题并且持续了两个小时以上，现象如下：
ERROR|org.hibernate.engine.jdbc.spi.SqlExceptionHelper|[SimpleAsyncTaskExecutor-52] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:150; busy:150; idle:0; lastwait:60000].
  最直接报错就是生产应用程序获取数据库连接无法正常获取，当时未进行定位问题的情况下只打印了线程栈快照，堆快照信息未保存，然后扩大数据库连接，最后重启，重启后无问题（当晚未留，第天定位）。

2.线程dump文件分析

这里涉及到信息安全问题，公司内网无法发送资料，所以本地再现了下，线程栈信息大致如下：

  我们在线程栈统计了正在运行的线程正好是数据库连接池的最大数目，这里我们就开始怀疑HashMap高并发非线程安全导致，占用数据库连接无法释放。由于没有堆信息进行佐证，我们无法石锤
但是这里很明显是p6spy打印sql日志引起的问题，我们可以到它的官网进行求证https://github.com/p6spy/p6spy/pull/318/commits/bba79de399f862b416db9d476e43f3af33ef90f7，

这里很明显进行了线程安全的改造处理。接下来我们需要做的就是升级p6spy版本号2.3.0以上
至此我们的问题基本可以说定位到了问题，但是我们还需要学会思考，大家知道HashMap高并发容易引起死循环，或者数据丢失，那么我们遇到问题时如何证明线程无法结束是因为HashMap导致的死循环呢？

3.问题复现及验证

1.复现HashMap死循环
这里我参考了仓颉图解系列文章的复现demo
代码如下：

package com.spring.test.deadmap;

import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.atomic.AtomicInteger;

public class HashMapThread extends Thread {
    private static AtomicInteger ai = new AtomicInteger(0);
    private static Map<Integer, Integer> map = new HashMap<Integer, Integer>(1);

    public void run() {
        while (ai.get() < 100000) {
            map.put(ai.get(), ai.get());
            ai.incrementAndGet();
        }
    }
}

package com.spring.test.deadmap;

public class Test {
    public static void main(String[] args) {
        HashMapThread hmt0 = new HashMapThread();
        HashMapThread hmt1 = new HashMapThread();
        HashMapThread hmt2 = new HashMapThread();
        HashMapThread hmt3 = new HashMapThread();
        HashMapThread hmt4 = new HashMapThread();
        hmt0.start();
        hmt1.start();
        hmt2.start();
        hmt3.start();
        hmt4.start();
    }
}

使用低版本jdk较容易复现死循环，多试几次。
2.证明线程无法结束是因为HashMap存在环
    我们需要借助堆快照形成堆内实例dump文件，借助MAT进行分析当前HashMap.Entry[]数组中的Entry链表是否存在循环引用

显然我们当前未结束线程的持有HashMap中存在环引用。