記一次 thread.blocked.count 線程過多的問題排查

問題現象：會經常出現block線程過多，但是瞬間又會恢復，因此較困難查詢到現場堆棧。jvm.thread.blocked.count  >= 50

一、由於現場難以抓取，因此無法用 Jstack 登錄機器查詢堆棧信息。

二、因為經過調研采用代碼的方式，抓取線上block時，線程堆棧信息。

private List<BlockThreadEntity> getBlockThreadList() {
        List<BlockThreadEntity> blockThreadInfoList = new ArrayList<>();
        final ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
        ThreadInfo[] threadInfos = threadBean.dumpAllThreads(false, false);

        if (threadInfos != null) {
            for (ThreadInfo threadInfo : threadInfos) {
                BlockThreadEntity entity = null;
                if (Thread.State.BLOCKED.equals(threadInfo.getThreadState())) {
                    entity = new BlockThreadEntity();
                    StringBuilder sb = new StringBuilder();
                    StackTraceElement[] stack = threadInfo.getStackTrace();
                    LockInfo lockInfo = threadInfo.getLockInfo();
                    String lockInfoString = null != lockInfo ? lockInfo.getClassName() : "";
                    for (StackTraceElement stackTraceElement : stack) {
                        sb.append("\n" + stackTraceElement.toString());
                    }
                    //記錄阻塞線程信息
                    entity.lockInfo = lockInfoString;
                    entity.stackTrace = sb.toString();
                    entity.threadId = String.valueOf(threadInfo.getThreadId());
                    entity.threadName = threadInfo.getThreadName();
                }
                if (entity != null) {
                    blockThreadInfoList.add(entity);
                }
            }
        }
        return blockThreadInfoList;
    }

二、經過一段時間的堆棧信息收集，找到關鍵的鎖信息

stacktrace:[
ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211)
ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175)
ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
com.***.scribe.logback.***LogAppender.append(***LogAppender.java:41)
com.***.scribe.logback.***LogAppender.append(***LogAppender.java:15)
ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441)
ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395)
ch.qos.logback.classic.Logger.info(Logger.java:599)

lockInfo:[ch.qos.logback.core.spi.LogbackLock]

  查看logbck的源碼，發現的確是用了 synchronized 鎖。

三、進一步源碼追蹤，發現使用的是同步日志，由於代碼中有一個調用量較大的地方，再打印日志， 關閉該出日志，問題解決。

四、補充：異步日志。

      AsyncAppenderBase 類

       BlockingQueue<E> blockingQueue = new ArrayBlockingQueue<E> 使用的是一個隊列。

       將日志時間放入隊列， 另一個線程，循環處理。 如果隊列滿了，會丟棄日志。