记一次 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;
    }

二、经过一段时间的堆栈信息收集,找到关键的锁信息

com.sankuai.meituan.banma.api.service.tcm.iface.BmTcmRiderApiThriftIface-8-thread-114815]
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.meituan.scribe.logback.BanmaLogAppender.append(BanmaLogAppender.java:41)
com.meituan.scribe.logback.BanmaLogAppender.append(BanmaLogAppender.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 锁。

记一次 thread.blocked.count 线程过多的问题排查

三、进一步源码追踪,发现使用的是同步日志,由于代码中有一个调用量较大的地方,再打印日志, 关闭该出日志,问题解决。

四、补充:异步日志。

      AsyncAppenderBase 类

       BlockingQueue<E> blockingQueue = new ArrayBlockingQueue<E> 使用的是一个队列。

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

上一篇:ROS2测评——探索ROS2的性能


下一篇:脱坑笔记