記一次應(yīng)用hang起問題處理

一. 程序主體

處理邏輯應(yīng)用開起10個線程分批處理任務(wù)，主體代碼如下：

      private Executor executor = Executors.newFixedThreadPool(THREAD_SIZE);
      for (LoanGroup group : groups) {
        LOGGER.info("商戶ID：{}轉(zhuǎn)換資產(chǎn)開始...", group.getMerchantId());
        Integer totalSize = loanMapper.countNeedCastLoans(group.getMerchantId());
        Integer times = totalSize % BATCH_SIZE == 0 ? totalSize / BATCH_SIZE : totalSize / BATCH_SIZE + 1;
        CountDownLatch countDownLatch = new CountDownLatch(times);
        for (int i = 0; i < times; i++) {
            final int time = i;
            executor.execute(new Runnable() {
                @Override
                public void run() {
                    try {
                        processBatch(group.getMerchantId(), time);
                    } catch (Exception e) {
                        LOGGER.error("商戶ID：{}開啟多線程轉(zhuǎn)換，轉(zhuǎn)換批次:{}...錯誤：{}", group.getMerchantId(), time, e);
                    } finally {
                        countDownLatch.countDown();
                    }
                }
            });
        }
        try {
            countDownLatch.await();
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

二. 問題現(xiàn)象

應(yīng)用執(zhí)行過程中發(fā)現(xiàn)任務(wù)日志不再打印，且可以確定的是當(dāng)前任務(wù)并沒有執(zhí)行完畢，通過jstat -gcutil 1000 10 采樣垃圾回收情況發(fā)現(xiàn)連續(xù)10次打印結(jié)果都沒有變化，通過jmap -heap pid 查看虛擬機內(nèi)存使用情況，發(fā)現(xiàn)虛擬機內(nèi)存還有足夠的空間使用。后又通過jstack pid dump出線程棧信息如下：

    Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.131-b11 mixed mode):
   "Attach Listener" #47 daemon prio=9 os_prio=31        tid=0x00007ffe38e7a000 nid=0x8707 waiting on condition [0x0000000000000000]
     java.lang.Thread.State: RUNNABLE
    "pool-1-thread-10" #46 prio=5 os_prio=31       tid=0x00007ffe33e8f000 nid=0x8503 waiting on condition         [0x00007000125a3000]
     java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000007415c10d8> (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:748)

  "pool-1-thread-9" #45 prio=5 os_prio=31 tid=0x00007ffe33167800 nid=0x8303 runnable [0x000070001249e000]
   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:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
- locked <0x0000000740cf8780> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2212)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1989)
at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3410)
at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:470)
at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3112)
at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2341)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2736)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2501)
- locked <0x0000000740cf36c8> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
- locked <0x0000000740cf36c8> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
- locked <0x0000000740cf36c8> (a com.mysql.jdbc.JDBC4Connection)
at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:493)

10個線程中6個線程處于waiting狀態(tài)，其他4個線程全如thread-9一樣處于RUNNABLE狀態(tài)。而且處于RUNNABLE狀態(tài)的線程全都阻塞在at com.mysql.jdbc.util.ReadAheadInputStream.fill處。

三.分析處理

根據(jù)現(xiàn)象猜測可能是網(wǎng)絡(luò)抖動丟包引起jdbc客戶端始終hang在套接字讀取數(shù)據(jù)處。

排查jdbc數(shù)據(jù)庫連接池配置以及mybatis的statement相關(guān)配置參數(shù)，發(fā)現(xiàn)并沒有對statement的timeout參數(shù)有相關(guān)配置，而且整個處理邏輯中也沒有用到事務(wù)。

定位問題應(yīng)該就是引網(wǎng)絡(luò)抖動引起而超時設(shè)置又沒有配置引起

解決方法：增加mybatis.configuration.default-statement-timeout 配置

參考資料：

1.http://www.importnew.com/2466.html
2.http://www.cubrid.org/blog/understanding-jdbc-internals-and-timeout-configuration