zkclient大量節點事件導致CPU飆升

概述

​ 項目背景 : 我們的某個服務是專門執行自動任務的 , 對外提供一個 jar 包里面有個自動任務的接口 , 然后各種自動任務的實現在其他各個項目, 並且作為服務提供者注冊到zookeeper 上 . 項目在開發階段時開發環境出現了CPU彪升 , 占用大量內存的現象.

現象

​ 先按 top 命令 ,然后再按大寫的 P

​ 可以看到 PID 29960 占的 CPU 已經達到 91% , (有時候也可能超過 100% , 這是因為多核 CPU 的原因) , 我們首先確定這個PID 對應的應用是什么

ps -aux | grep '29960'

​

​ 比如說這個應用是 admin , 下面我們在查看一下該 PID 下那個線程消耗的 CPU 資源高 .

top -p 41843 -H

​

​ OK , 這里我們已經知道了該 PID 的最忙的線程, 我們稍微看一下這個線程在干什么事

strace -p 30021

​ 可以看到多個線程正在進行大量的自旋中(自旋鎖) , 那么下面我們利用 jstace 命令進行查看這個線程的位置和堆棧 . 使用 jstace
找到某個線程的時候會用到16進制

printf "%x\n" 30021

​ 然后使用 jstace 命令

jstack -l 30021 | grep 0x7545 -A20 

​ ok , 我們每過幾秒在運行一下上面的命令就可以知道該線程是否給阻塞了.

dump 內存文件分析

​ 我們通過上面了知道 CPU 飆升地厲害, 而內存也占用了不少, 於是我們 dump 下了文件進行分析, 我們用 jmap 命令, 然后放大 MAT工具進行分析.

jmap  -dump:live,format=b,file=2021-7-17-21-05.dump 29960

​ 一般dump 下來的文件比較大, 我們可以壓縮一下文件

tar -zcvf 2021-7-17-21-05.gz  2021-7-17-21-05.dump

​ 然后下載下來扔到 MAT工具里

​ 可以看到下面的分析, 其中畫紅色圈圈的需要關注一下, 我們首先看一下創建實例的數量排序

​ 可以看到 zkClient里面的一個內部類對象創建了很多個實例, 並且從占用的內存也可以看出確實是這些對象占用了大量的內存

​ 我們看一下引用該對象的有哪些呢? 下面我們先來看看該類在哪里定義, 又為何創建那么多的對象

​ dubbo 框架應用了它, dubbo進入了我們觀察的視野, 再看一下大對象分析,

​ 可以看到 zkClient 這個類的某個實例占的內存高達 95% 也就是大概 5G 左右的內存都是消耗在這個對象上的, 我們點開它的屬性,發現了里面的一個隊列占了大部分的內存比例, 而這些對象都有個特點就是 , zkClient 的某個字段都是 : Children of /dubbo/com.midea.mdp.dubbo.service.SchedulerDubboJobService/providers changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@7ecbb7e6
再看看下面的圖

​ 這個隊列的數量達到了千萬級別的數目, 非常不正常. OK , 下面將根據我們的線索, 我們將會分析占用內存和占用CPU 的原因

class ZkEventThread extends Thread {

    private static final Logger LOG = LoggerFactory.getLogger(ZkEventThread.class);

    private BlockingQueue<ZkEvent> _events = new LinkedBlockingQueue<ZkEvent>();

    private static AtomicInteger _eventId = new AtomicInteger(0);

    static abstract class ZkEvent {

        private String _description;

        public ZkEvent(String description) {
            _description = description;
        }

        public abstract void run() throws Exception;

        @Override
        public String toString() {
            return "ZkEvent[" + _description + "]";
        }
    }

    ZkEventThread(String name) {
        setDaemon(true);
        setName("ZkClient-EventThread-" + getId() + "-" + name);
    }

    @Override
    public void run() {
        LOG.info("Starting ZkClient event thread.");
        try {
            while (!isInterrupted()) {
                ZkEvent zkEvent = _events.take();
                int eventId = _eventId.incrementAndGet();
                LOG.debug("Delivering event #" + eventId + " " + zkEvent);
                try {
                    zkEvent.run();
                } catch (InterruptedException e) {
                    interrupt();
                } catch (ZkInterruptedException e) {
                    interrupt();
                } catch (Throwable e) {
                    LOG.error("Error handling event " + zkEvent, e);
                }
                LOG.debug("Delivering event #" + eventId + " done");
            }
        } catch (InterruptedException e) {
            LOG.info("Terminate ZkClient event thread.");
        }
    }

    public void send(ZkEvent event) {
        if (!isInterrupted()) {
            LOG.debug("New event: " + event);
            _events.add(event);
        }
    }
}

​ 該類繼承了 Thread , 可以知道是線程任務類, 該類持有一個阻塞隊列, 執行的任務就是不斷從中拿去任務出來,然后進行處理. 我們通過代碼可以知道該線程的作用是處理 zk 發過來的事件.

​ 我們可以看到這個 EventThread 在 zkClient 中進行初始化並運行線程執行任務的調用. 知道了這些 , 我分析有兩種情況會導致這種現象

1. 大量發過來的 event ,直接壓垮了處理事件的線程 , event 都在阻塞隊列中, 所以我們可以看到那么多的自旋鎖在不斷嘗試獲得鎖
2. 隊列的處理過程中遇到了阻塞 ,相當於生產者的效率大大大於消費者, 所以時間久了自然就堆積了.
   我先對第二種情況進行了驗證, 這里用到了阿里的一個工具 arthas,

trace org.I0Itec.zkclient.ZkEventThread$ZkEvent run

​ 我們可以看到處理事件的線程並沒有啥問題 , 處理一個任務都是以毫秒計算的. ok ,既然第二種猜想是不成力的, 那么第一種呢?假設第一種猜想是正確的, 那么事件為什么又會產生那么多呢? 根據我們前面的 MAT 的分析 , 看到了都是
Children of /dubbo/com.xx.mdp.dubbo.service.SchedulerDubboJobService/providers changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@7ecbb7e6
​ 這一個相關的事件 ,於是我在代碼中進行了跟蹤, 找到了事件插入隊列的地方 :

​ 依然使用 trace命令進行查看插入隊列的方法是否正常, 判斷是否是應該插入的速率遠遠大於取出的速率

通過上面的分析, 我們基本可以確定的是 :

1. 大量的 zk 節點事件阻塞在隊列中, 導致自旋鎖, 導致CPU 上升, 由於大量數量事件對象導致占用了大量的內存
2. 一種可能是由於事件太多, 導致事件堆積; 處理事件的線程處理效率低導致大量事件堆積, 從上面的 trace 查看已經證明處理線程並沒有阻塞, 處理速度也正常, 下面我們將按照大量事件導致事件堆積的思路進行排查

項目背景

​ 其他項目提供自動任務的提供者 , 最后都由 admin 進行調用消費, zk 節點情況如下 。 admin 應用作用自動任務的執行者, 會定時去調用外部的定時任務接口, 而外部的定時任務接口是使用dubbo, 注冊在 zk 上的某個固定節點下, 那么外部的應用是 dubbo 提供者, 而 admin 應用作為消費者,我們剛好在該環境內進行開發測試, 會頻繁地上下線應用. 節點結構如下圖,

驗證猜想

​ 也就是說所有的消費者都在 admin 應用, 而外部的應用充當提供者 , 既然節點是 zk 發的, 那么有沒有可能是由於頻繁地上下線導致的zk節點變化事件大量產生呢?於是我做了以下實驗 , 通過打印日志的方式得到收到事件的數量.

demo案例模擬

為了模擬dubbo 消費者和生產者之間上下線產生的節點變化事件 , 我寫了一個 consumer 項目模擬成 admin 一樣的角色, 對外提供接口給外圍系統實現, 外圍作為提供者注冊到 zk 節點, 可以看到提供者有4個. 我們將模擬以下場景

consumer 消費者

provider1 提供者

provider2 提供者

步驟一 : 部分提供者下線

​ 下面兩個提供者下線收到的事件 , 共四個 , 下線兩個 , 共收到 4個事件 .

步驟二 : 部分提供者上線

​ 剛才下線了兩個提供者 , 剩下兩個提供者 , 現在我們再重新上線 . 可以看到我們此時收到的是 12 - 4 = 8個事件.

步驟三 : 再次下線

步驟四 : 再次上線

demo 總結

​ 我們通過上面基本上確定了是 provider 上線會觸發上線事件 ，並且是數量是 上線提供者數量 * 集體消費者數量 ，頻繁上下線會觸發事件的數量是可怕的， 而出現事件的線程剛好是單線程 ， 並且消費者的應用只有一個 ： admin , 於是大量的事件打滿了出現事件的線程 ， 全都堆積在阻塞隊列中進行自旋阻塞 ，從而 CPU 上升 ， 內存上升。

總結

​ 通過這一次的分析, 熟悉了一下排查問題的流程, 並通過分析驗證了自己的猜想.

參考資料

• https://www.orchome.com/435
• https://www.cnblogs.com/suixianlong/articles/3569433.html
• https://www.cnblogs.com/jiqing9006/p/9270504.html
• https://blog.csdn.net/fuyuwei2015/article/details/73256425 (Linux下如何定位Java進程CPU利用率過高原因)
• https://blog.csdn.net/vic_qxz/article/details/80416456 (Linux下如何定位Java進程CPU利用率過高原因)