爲何一段看似正確的代碼會致使DUBBO線程池被打滿

時間  2021-08-14
標籤 java linux web spring apache windows 緩存 服務器 微信 markdown 欄目 Dubbo 简体版
原文   原文鏈接

歡迎你們關注公衆號「JAVA前線」查看更多精彩分享文章，主要包括源碼分析、實際應用、架構思惟、職場分享、產品思考等等，同時歡迎你們加我微信「java_front」一塊兒交流學習java

1 一個公式

咱們在以前一篇文章中用一個公式分析了爲何DUBBO線程池爲何會打滿，在本文開始時咱們不妨先回顧一下這個公式：一個公司有7200名員工，天天上班打卡時間是早上8點到8點30分，每次打卡系統耗時5秒。請問RT、QPS、併發量分別是多少？linux

RT表示響應時間，問題已經告訴了咱們答案：web

RT = 5spring

QPS表示每秒查詢量，假設簽到行爲平均分佈：apache

QPS = 7200 / (30 * 60) = 4windows

併發量表示系統同時處理的請求數量：緩存

併發量 = QPS x RT = 4 x 5 = 20服務器

根據上述實例引出以下公式：微信

併發量 = QPS x RTmarkdown

若是系統爲每個請求分配一個處理線程，那麼併發量能夠近似等於線程數。基於上述公式不難看出併發量受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) 配置文件

<beans>
  <dubbo:application name="java-front-provider" />
  <dubbo:registry address="zookeeper://127.0.0.1:2181" />
  <dubbo:protocol name="dubbo" port="9999" />
  <dubbo:service interface="com.java.front.dubbo.demo.provider.HelloService" ref="helloService" />
</beans>
複製代碼

(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) 配置文件

<beans>
  <dubbo:application name="java-front-consumer" />
  <dubbo:registry address="zookeeper://127.0.0.1:2181" />
  <dubbo:reference id="helloService" interface="com.java.front.dubbo.demo.provider.HelloService" timeout="10000" />
</beans>
複製代碼

(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
複製代碼

(a) 如何下載

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

(b) 如何運行

java -jar jca469.jar
複製代碼

(c) 如何分析

咱們用這個工具打開dump.log文件，選擇工具欄餅狀圖標分析線程狀態：

1.jpg

咱們發現大量線程阻塞在HelloServiceImpl第48行，找到相應代碼位置：

public class HelloServiceImpl implements HelloService {

    // 省略代碼......
    
    @Override
    public String getValueFromCache(String key) {
        return MyCache.getValueFromCache(key); // 第48行
    }
}
複製代碼

咱們假設若是MyCache.getValueFromCache這個方法中存在耗時操做，那麼線程應該阻塞在這方法的某一行，可是最終居然阻塞在HelloServiceImpl這個類，這說明是阻塞發生在MyCache這個類初始化上。咱們再回顧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) {
        }
    }
}
複製代碼

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沒有初始化完成就被大量調用的狀況，致使大量線程阻塞在初始化方法上，最終致使線程池打滿。因此當流量逐漸增大時，量變引發了質變，原來不是問題的問題也暴露了出來，這須要引發咱們的注意，但願本文對你們有所幫助。

歡迎你們關注公衆號「JAVA前線」查看更多精彩分享文章，主要包括源碼分析、實際應用、架構思惟、職場分享、產品思考等等，同時歡迎你們加我微信「java_front」一塊兒交流學習

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程