记一次 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> 使用的是一个队列。

       将日志时间放入队列， 另一个线程，循环处理。 如果队列满了，会丢弃日志。