为什么一段看似正确的代码会导致DUBBO线程池被打满

ゝ一纸荒年。 2021-09-25 08:32 179阅读 0赞

> 欢迎大家关注公众号「JAVA前线」查看更多精彩分享文章，主要包括源码分析、实际应用、架构思维、职场分享、产品思考等等，同时欢迎大家加我微信「java\_front」一起交流学习

# 1 一个公式 #

我们在之前一篇文章中用一个公式分析了为什么DUBBO线程池为什么会打满，在本文开始时我们不妨先回顾一下这个公式：一个公司有7200名员工，每天上班打卡时间是早上8点到8点30分，每次打卡系统耗时5秒。请问RT、QPS、并发量分别是多少？

RT表示响应时间，问题已经告诉了我们答案：

> RT = 5

QPS表示每秒查询量，假设签到行为平均分布：

> QPS = 7200 / (30 \* 60) = 4

并发量表示系统同时处理的请求数量：

> 并发量 = QPS x RT = 4 x 5 = 20

根据上述实例引出如下公式：

> 并发量 = QPS x RT

如果系统为每一个请求分配一个处理线程，那么并发量可以近似等于线程数。基于上述公式不难看出并发量受QPS和RT影响，这两个指标任意一个上升就会导致并发量上升。

但是这只是理想情况，因为并发量受限于系统能力而不可能持续上升，例如DUBBO线程池就对线程数做了限制，超出最大线程数限制则会执行拒绝策略，而拒绝策略会提示线程池已满，这就是DUBBO线程池打满问题的根源。

# 2 一段代码 #

现在我们分析一段正确的代码为什么导致DUBBO线程池打满：MyCache是一个缓存工具，初始化时从很多文件中读取数据内容至内存，获取时直接从内存获取。

public class MyCache { 
        private static Map<String, String> cacheMap = new HashMap<String, String>();
    
        static { 
            initCacheFromFile();
        }
    
        private static void initCacheFromFile() { 
            try { 
                long start = System.currentTimeMillis();
                System.out.println("init start");
                // 模拟读取文件耗时
                Thread.sleep(10000L);
                cacheMap.put("K1", "V1");
                System.out.println("init end cost " + (System.currentTimeMillis() - start));
            } catch (Exception ex) { 
            }
        }
    
        public static String getValueFromCache(String key) { 
            return cacheMap.get(key);
        }
    }

## 2.1 生产者 ##

### (1) 服务声明 ###

public interface HelloService { 
        public String getValueFromCache(String key);
    }
    
    @Service("helloService")
    public class HelloServiceImpl implements HelloService { 
    
        @Override
        public String getValueFromCache(String key) { 
            return MyCache.getValueFromCache(key);
        }
    }

### (2) 配置文件 ###

### (3) 服务发布 ###

public class Provider { 
        public static void main(String[] args) throws Exception { 
            String path = "classpath*:META-INF/spring/dubbo-provider.xml";
            ClassPathXmlApplicationContext context = new ClassPathXmlApplicationContext(path);
            System.out.println(context);
            context.start();
            System.in.read();
        }
    }

## 2.2 消费者 ##

### (1) 配置文件 ###

### (2) 服务消费 ###

public class Consumer { 
        public static void main(String[] args) throws Exception { 
            ClassPathXmlApplicationContext context = new ClassPathXmlApplicationContext(new String[] {  "classpath*:META-INF/spring/dubbo-consumer.xml" });
            context.start();
            System.out.println(context);
            // 模拟大量请求
            for (int i = 0; i < 1000; i++) { 
                new Thread(new Runnable() { 
                    @Override
                    public void run() { 
                        HelloService helloService = (HelloService) context.getBean("helloService");
                        String result = helloService.getValueFromCache("K1");
                        System.out.println(result);
                    }
                }).start();
            }
        }
    }

## 2.3 运行结果 ##

我们观察日志内容发现线程池打满信息：

NettyServerWorker-5-1  WARN support.AbortPolicyWithReport: 
    [DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-1.1.1.1:9999, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 201 (completed: 1), 
    Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://1.1.1.1:9999!, dubbo version: 2.7.0-SNAPSHOT, current host: 1.1.1.1

# 3 一个工具 #

根据第一章节介绍的公式和代码片段，我们不难推测大概率是因为RT上升导致线程池打满，但如果需要分析详细原因还不能就此止步，还需要结合线程快照进行分析。线程快照还有一个作用就是如果线上服务器突然报线程池打满错误，我们不能立刻定位问题代码位置，这就需要通过线程快照进行分析。

## 3.1 jstack ##

获取线程快照第一种方式是jstack命令，这个命令可以根据JAVA进程号打印线程快照，使用方法分为三个步骤，第一确定JAVA进程号，第二打印线程快照，第三分析线程快照。

### (1) 确定JAVA进程号 ###

jps -l

### (2) 打印线程快照 ###

假设第一步得到JAVA进程号为5678

jstack 5678 > dump.log

### (3) 分析线程快照 ###

现在我们就要分析快照文件dump.log，我们当然可以直接打开快照文件进行分析，也可以借助工具进行分析，我通常一款IBM开发的免费线程快照分析工具：

IBM Thread and Monitor Dump Analyzer for Java

#### 如何下载 ####

https://public.dhe.ibm.com/software/websphere/appserv/support/tools/jca/jca469.jar

#### 如何运行 ####

java -jar jca469.jar

#### 如何分析 ####

我们用这个工具打开dump.log文件，选择工具栏饼状图标分析线程状态：

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3dvc2hpeHV5ZQ_size_16_color_FFFFFF_t_70]

我们发现大量线程阻塞在HelloServiceImpl第48行，找到相应代码位置：

public class HelloServiceImpl implements HelloService { 
    
        // 省略代码......
        
        @Override
        public String getValueFromCache(String key) { 
            return MyCache.getValueFromCache(key); // 第48行
        }
    }

我们假设如果MyCache.getValueFromCache这个方法中存在耗时操作，那么线程应该阻塞在这方法的某一行，但是最终竟然阻塞在HelloServiceImpl这个类，这说明是阻塞发生在MyCache这个类初始化上。我们再回顾MyCache代码，发现确实是初始化方法消耗了大量时间，证明根据线程快照分析的正确性。

## 3.2 DUBBO线程快照 ##

第二种获取线程快照的方式在DUBBO线程池拒绝策略源码中，我们分析源码知道每当出现线程池打满情况时DUBBO都会打印线程快照。

public class AbortPolicyWithReport extends ThreadPoolExecutor.AbortPolicy { 
        protected static final Logger logger = LoggerFactory.getLogger(AbortPolicyWithReport.class);
        private final String threadName;
        private final URL url;
        private static volatile long lastPrintTime = 0;
        private static Semaphore guard = new Semaphore(1);
    
        public AbortPolicyWithReport(String threadName, URL url) { 
            this.threadName = threadName;
            this.url = url;
        }
    
        @Override
        public void rejectedExecution(Runnable r, ThreadPoolExecutor e) { 
            String msg = String.format("Thread pool is EXHAUSTED!" +
                                       " Thread Name: %s, Pool Size: %d (active: %d, core: %d, max: %d, largest: %d), Task: %d (completed: %d)," +
                                       " Executor status:(isShutdown:%s, isTerminated:%s, isTerminating:%s), in %s://%s:%d!",
                                       threadName, e.getPoolSize(), e.getActiveCount(), e.getCorePoolSize(), e.getMaximumPoolSize(), e.getLargestPoolSize(),
                                       e.getTaskCount(), e.getCompletedTaskCount(), e.isShutdown(), e.isTerminated(), e.isTerminating(),
                                       url.getProtocol(), url.getIp(), url.getPort());
            logger.warn(msg);
            // 打印线程快照
            dumpJStack();
            throw new RejectedExecutionException(msg);
        }
    
        private void dumpJStack() { 
            long now = System.currentTimeMillis();
    
            // 每10分钟输出线程快照
            if (now - lastPrintTime < 10 * 60 * 1000) { 
                return;
            }
            if (!guard.tryAcquire()) { 
                return;
            }
    
            ExecutorService pool = Executors.newSingleThreadExecutor();
            pool.execute(() -> { 
                String dumpPath = url.getParameter(Constants.DUMP_DIRECTORY, System.getProperty("user.home"));
                System.out.println("AbortPolicyWithReport dumpJStack directory=" + dumpPath);
                SimpleDateFormat sdf;
                String os = System.getProperty("os.name").toLowerCase();
    
                // linux文件位置/home/xxx/Dubbo_JStack.log.2021-01-01_20:50:15
                // windows文件位置/user/xxx/Dubbo_JStack.log.2020-01-01_20-50-15
                if (os.contains("win")) { 
                    sdf = new SimpleDateFormat("yyyy-MM-dd_HH-mm-ss");
                } else { 
                    sdf = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss");
                }
                String dateStr = sdf.format(new Date());
                try (FileOutputStream jStackStream = new FileOutputStream(new File(dumpPath, "Dubbo_JStack.log" + "." + dateStr))) { 
                    JVMUtil.jstack(jStackStream);
                } catch (Throwable t) { 
                    logger.error("dump jStack error", t);
                } finally { 
                    guard.release();
                }
                lastPrintTime = System.currentTimeMillis();
            });
            pool.shutdown();
        }
    }

从下面线程快照文件中我们看到，200个DUBBO线程也都是执行在HelloServiceImpl第48行，从而也可以定位到问题代码位置。但是DUBBO打印线程快照不是jstack标准格式，所以无法使用IBM工具进行分析。

DubboServerHandler-1.1.1.1:9999-thread-200 Id=230 RUNNABLE
    at com.java.front.dubbo.demo.provider.HelloServiceImpl.getValueFromCache(HelloServiceImpl.java:48)
    at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)
    at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:56)
    at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:85)
    at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56)

# 4 一些思考 #

MyCache工具的修改方法也并不复杂，可以将其交给Spring管理，通过PostConstruct注解进行初始化，并且将获取缓存方法声明为对象方法。

其实我们发现MyCache类语法并没有错误，在静态代码块执行初始化操作也并非不可。但是由于调用者流量很大，发生了MyCache没有初始化完成就被大量调用的情况，导致大量线程阻塞在初始化方法上，最终导致线程池打满。所以当流量逐渐增大时，量变引起了质变，原来不是问题的问题也暴露了出来，这需要引起我们的注意，希望本文对大家有所帮助。

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3dvc2hpeHV5ZQ_size_16_color_FFFFFF_t_70]: /images/20210923/d0e6c6ec78c240a880790f6cb823d1c8.png