別讓這樣的定時任務拖垮你的網站

快樂的皮拉夫發表於2023-04-25

背景介紹

最近有同事反饋線上的 MySQL 查詢速度非常慢,我開啟阿里雲的控制檯看了看,一看嚇了一跳,線上的 MySQL CPU 使用率居高不下,平均值都在80%以上,而且已經持續了有一段時間了。80%!!!這還了得,勢必要排查下到底是什麼原因導致 CPU 飆的這麼高。

0OMnnWSTED.png!large

分析定位

根據以往經驗,導致 MySQL CPU 過高的罪魁禍首一般是慢查詢,於是先去收集了一波慢查詢的 SQL。當我把能最佳化的慢查詢最佳化完一遍以後,信心滿滿地回到了控制檯,重新整理頁面,等待奇蹟的發生時,結果卻被打臉了—— CPU 並沒有明顯的變化。

難道問題不是出在慢查詢上?

我又把焦點停在了 MySQL 的監控指標皮膚上:

w5EHgH476B.png!large

除了 CPU 異常之外,圖中有幾個異常的指標引起了我的注意:

  • 流量吞吐 - mysql.bytes_sent:8000 KB
  • QPS:1200 次/秒
  • 會話連線 - mysql.total_session:150
  • 執行次數 - mysql.select_ps:500 次/秒

名詞解釋:

mysql.bytes_sent:服務端平均每秒傳送給客戶端的位元組數
QPS:每秒執行的查詢數
mysql.total_session:當前全部會話
mysql.selec_ps:平均每秒select語句執行次數

這些指標幾乎與 CPU 的變化趨勢保持一致,說明有可能直接或者間接導致了 CPU 的負荷過高。

根據主觀推斷,流量吞吐異常可能是因為單次查詢資料返回量過大,QPS 和每秒執行的 select 查詢次數異常可能是查詢的頻次過高,會話連線數異常可能存在未正常釋放的連線。什麼業務場景可能會同時觸發這幾個條件呢?

就在我不知所措的時候,我在控制檯 CPU 異常時間點的快照中發現了需要最佳化的查詢一欄,在第一條 SQL 後面的最佳化建議中寫著 限流 二字,限流???為什麼提示我限流呢?我毫不猶豫地點開詳情:

2di3B3qNLb.png!large

根據耗時佔比達到 64.08% 不難看出這條查詢嫌疑重大,再根據統計時間和執行次數分析:一分鐘時間內執行了 241 次!!!平均每秒就要執行 4 次,什麼查詢需要每秒鐘執行 4 次呢?

還好快照中儲存了我們溯源的關鍵資訊:根據客戶端 IP 和埠號,我們可以定位到「案發第一現場」,再根據 SQL 裡的關鍵字資訊,我們不難定位到具體的程式碼位置,接下來就該揭開「作案人」的神秘面紗了!

為了方便分析,我們這裡擷取部分主要的程式碼片段進行分析:

/**
 * 自動確認收貨
 * PS: 定時任務,每五分鐘執行一次
 */
public function autoConfirmReceipt ()
{
    // 查詢條件:訂單狀態為已發貨,發貨時間超過15天且不存在售後
     $condition = [
        'order_status' => 2,    // 訂單狀態:已發貨
        'refund_status' => 0,    // 售後狀態:無售後
        'delivered_at' => ['<', time() - 15 * 86400]    // 發貨時間:超過15天
    ];

    while (1) {
        // 查詢多條記錄,引數依次為:查詢條件,返回欄位,返回條數
        $list = $this->orderModel->getMore($condition, ['*'], 100);
        if (!$list) { 
            break;        
        } 

        foreach ($list as $item) {
            try { 
                // 開啟事務
                DB::beginTransaction();
                $orderId = $item['id'] ?? '';               // 訂單ID
                $shareUid = $item['share_uid'] ?? '';       // 分享人ID

                // 邏輯一:根據主鍵更新記錄
                $ret = $this->orderModel->updateByKey($orderId, [
                    'order_status' => 3,        // 訂單狀態:已收貨
                     'confirmed_at' => time()    // 確認收貨時間
                 ]); 
                if (!$ret) {
                    throw new Exception('自動確認收貨更新訂單資訊失敗。');
                 }

                 // 邏輯二:根據訂單更新分享人佣金資訊
                 $ret = $this->commissionModel->updateByCondition(
                    [
                        'order_id' => $orderId,     // 訂單ID
                        'share_uid' => $shareUid,   // 分享人ID
                    ],
                    [
                        'status' => 2,          // 已到賬
                        'arrived_at' => time(), // 到賬時間
                    ]
                ); 
                if (!$ret) { 
                    throw new Exception('自動確認收貨更新佣金資訊失敗。');
                 }

                 // 提交事務
                 DB::commit(); 
            } catch (Exception $e) { 
                Log::error('自動確認收貨失敗。', [
                    'line' => $e->getLine(), 
                    'message' => $e->getMessage(), 
                    'item' => $item, 
                ]); 

                // 回滾事務
                DB::rollback(); 
                continue;
            }
        }
        // 貼心的沉睡
        sleep(5); 
    }
}

看完上述程式碼,感覺有何不妥?

從邏輯上看,每次從表中篩選符合條件的資料,然後進行更新,更新完以後再執行一段相關的業務邏輯,感覺也沒什麼不妥之處啊?理論上講,如果表中僅有少量需要處理的資料,一次查詢即可處理完畢,下一次迴圈查詢的時候返回空直接就退出了,也不會有什麼壓力啊,即使需要執行多次查詢,還有個貼心的 sleep 沉睡,理論上也不會有太大壓力,為何成了「作案兇手」呢?

讓我們把焦點再回到提示限流的 SQL 詳情裡,有個線索需要引起我們的重點關注:該條 SQL 在一分鐘的時間裡執行了 241 次,什麼概念?平均每秒就要執行4次。

可問題是我們程式中還有個貼心的沉睡 sleep ,就算查詢時間、更新時間都忽略,一分鐘也就最多執行 12 次啊,怎麼能達到 241 次呢?(實測執行一次批次查詢的 SQL 大概需要 5s 左右,這就更解釋不通了)

難不成這段程式碼還能自動變身?

既然正常邏輯解釋不通,那就不妨先跟蹤下程式看看是否存在異常。正常來講的話,程式會在每五分鐘時被呼叫,如果查詢不為空的話程式至少會持續 5s 以上(5s 沉睡),所以我們儘量卡在分鐘數是 5 的倍數的時間點檢視程式狀態(如:12:00,12:05等)。OK,分析完,我們選個吉利的時間點直接使用 ps aux | grep '{keyword}' 進行分析,結果令我大跌眼鏡:

居然同時有 100 多個程式在執行!!!WTF???

冷靜片刻,我大概已經想到是什麼原因了。不急揭曉答案,讓我們稍微換個緯度,透過時序圖來大致分析一下:

正常情況下我們的程式呼叫應該是長下面這個樣子的:

Z2ArW4ekLz.png!large

這裡有個依賴關係,定時任務呼叫指令碼啟動程式以後,程式的退出依賴於批次查詢的結果是否為空,如果結果集一直不為空的話,那麼程式將一直無法退出,而這並不會影響下一次定時任務的正常執行,其結果就是每一次透過定時任務啟動的程式都變成了無法退出的 守護程式,要想退出除非奇蹟出現 —— 查詢結果集為空主動退出或者 try 外層丟擲異常導致程式退出。

是什麼原因會導致查詢結果集一直不為空呢?try catch + 事務

仔細看一眼程式碼邏輯不難發現,程式碼的異常處理邏輯放在了批次查詢的內層,當內層的更新邏輯報錯時,事務回滾,這就導致批次查詢的資料無法正常更新,但是並不會影響到下一次批次查詢的執行。因此也就形成了 批次查詢 -> 事務啟動 -> 程式異常,事務回滾 -> 下一次批次查詢 的惡性迴圈。

真相是不是真的像我們所說的一樣呢?所幸程式中在內層拋異常的位置都有列印日誌,根據關鍵字去搜尋日誌,果真和我們預測的一樣 —— 在更新使用者佣金的位置,因為找不到對應資料,導致更新失敗(可能是異常資料被特殊處理了)。同時我們還意外地發現,每天記錄的日誌檔案大小達到了 3 個G左右,每天報錯記錄的行數更是達到了 500 萬行之多,不可思議!!!

明確了問題所在,接下來就是考慮如何進行最佳化了。

其實最佳化思路並不難,只要將這種 迴圈批次獲取 的方式改為 迴圈分頁獲取 就可以了,示例如下:

...
$page = 1;
$pageSize = 50;

while (1) {
    // 分頁查詢多條記錄,引數依次為:查詢條件,返回欄位,分頁,分頁大小
    $list = $this->orderModel->getMoreWithPage($condition, ['*'], $page, $pageSize); 
    if (!$list) { 
        break;    
    }       
    $page++;
    ...
}

說明:這裡還有其他最佳化的細節,因為不是這裡討論的重點,所以不再展開最佳化。

或許看到這裡,你還會有些許疑問:雖然改成分頁查詢,但是因為更新邏輯存在問題,每一次定時任務不還是會執行重複的查詢嗎?沒錯,但是這樣最佳化完以後,我們的定時任務現在可以在執行完每次的查詢後主動結束程式,從而避免了上百個程式同時呼叫 MySQL 查詢的 堵車情況 ,MySQL 的負荷自然也不會高的離譜。

最佳化完程式碼以後,我們又清理掉多餘的程式,然後迫不及待地重新整理著 MySQL 監控頁面,等待奇蹟發生!結果和預期一致:

JkmDS11HeD.png!large

看著降下來的曲線,這感覺,一個字:爽!

總結

透過處理這個問題,我們可以總結到以下經驗:

  • 使用定時任務執行批次查詢時,一定要考慮程式是否會主動退出。如果程式存在無法主動退出的可能,帶來的後果將是不可估量的。
  • 縱觀全域性,出現這種問題的主要原因是在編碼的時候缺乏程式擴充套件性的考慮,特別是在團隊協作開發的時候。站在歷史發展的角度思考,一開始編碼人員可能考慮到只有一個更新訂單表的操作,出現 可查詢不可更新 事件的機率性極低,所以才選擇了這種簡單的批次處理方案,而且上線初期確實也沒有出現異常問題。但是某一天另一個開發人員需要在自動確認收貨的邏輯裡追加一些佣金處理邏輯,發現有現成可用的指令碼,於是稍加調整,改成了上面程式碼的樣子。自此,潘多拉魔盒已經悄然準備就緒,只等一個被開啟的機會。
  • 程式碼的作者在編寫上述邏輯時,可能受到 佇列 處理思路的影響,腦海中首先想到的就是 push and pop 操作,再換成從 MySQL 中獲取資料,結合定時任務的處理邏輯不就 OK 了麼。這是我推測的結果,如果被我不幸說中的話,那我想給作者溫馨提示一下,在佇列的處理邏輯裡,程式是以守護程式的形式存在的,定時任務或者手動啟動只是作為佇列的啟動或者重啟方式。在不考慮多程式的情況下,在處理邏輯中必須有 程式狀態 的判斷邏輯,這樣做的目的就是為了避免無限開啟程式。如果考慮透過多程式增加處理效率的話,redis 佇列本身因為具有 原子性 的特性,多開程式尚無大礙。而 MySQL 則一般需要透過特殊的邏輯處理(比如透過程式編號對資料取模處理)來保證操作的原子性。
  • 優秀的程式碼是需要充分考慮 擴充套件性 的,擴充套件性越強,其維護成本越低。反之,隨著時間的推移和系統複雜性的增加,帶來的後果可能是災難性的。
本作品採用《CC 協議》,轉載必須註明作者和本文連結

相關文章