问题现象:会经常出现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 锁。
三、进一步源码追踪,发现使用的是同步日志,由于代码中有一个调用量较大的地方,再打印日志, 关闭该出日志,问题解决。
四、补充:异步日志。
AsyncAppenderBase 类
BlockingQueue<E> blockingQueue = new ArrayBlockingQueue<E> 使用的是一个队列。
将日志时间放入队列, 另一个线程,循环处理。 如果队列满了,会丢弃日志。