記一次 Laravel 定時任務不按時執行的 Bug 追查記錄及修復方案

leo發表於2018-08-19
Laravel

背景

我司的某個 Laravel 專案，通過 Laravel 的定時任務模組在每天晚上 8 點鐘群發訊息給使用者，之前一直執行良好。前天發現使用者收到通知的時間大約在晚上 10 點多，當時以為只是伺服器負載比較高而導致的傳送較慢，就沒有太在意，然而昨天的訊息居然延遲到了次日凌晨一點多才送達，而且是所有使用者都是在那個時間點收到的，而不是想象中從晚上 8 點開始逐漸收到。

山窮水盡

首先看出問題的定時任務的執行邏輯：

  1. 從資料庫中查詢出所有符合條件的使用者
  2. 逐個呼叫 Laravel 的 Notification 模組進行訊息通知，對應的 Notification 類開啟了 ShouldQueue，因此真正的訊息推送會由給佇列來處理。

由於我們這個專案才剛啟動不久，使用者量在萬級別，因此不太可能是第一步出問題，通過檢視相對應的 SQL 執行記錄，耗時在數百毫秒，因此可以排除步驟 1。

接下來看步驟 2，由於定時任務本身不執行具體的傳送訊息動作，只是把任務序列化之後儲存到 Redis，這個步驟的效率完全取決於 Redis 伺服器的吞吐量，於是檢視晚上 8 點到次日凌晨 1 點 Redis 伺服器的負載，發現都不高，因此可以排除是因為 Redis 伺服器負載過高而導致的問題。

既然定時任務本身沒有問題，那就開始排查具體執行推送任務的佇列處理器。

由於這個專案業務量還不大，只用了一臺伺服器來執行佇列處理器，使用 Supervisor 啟動了 4 個佇列處理器，啟動命令是

php artisan queue:work --sleep=3 --tries=3 --timeout=3600 --memory=512

檢視該伺服器在晚上 8 點到次日凌晨 1 點的負載，也屬於正常水平，不像是因為其他佇列任務佔用了佇列處理器資源而導致推送佇列沒有被及時處理。

這下有點懵逼，感覺一切指標都正常，但就是出毛病了。

柳暗花明

在各項指標沒有問題的情況下，那隻好通過日誌來嘗試復原當時伺服器上發生的事情。

根據之前的分析，我先假定在晚上 8 點的時候，定時任務已經完成了自己的工作，將需要推送的訊息存入了 Redis，所以我檢視了佇列處理器的輸出日誌，這個是通過 Supervisor 的配置實現的，在 Supervisor 的配置中通過

stdout_logfile=/project_path/storage/logs/worker.log

可以將佇列的輸出重定向到這個日誌檔案。

使用 less 命令檢視這個日誌檔案，並跳轉到晚上 8 點左右的日誌，裡面的內容類似：

[2018-08-18 20:06:54][ZyW9eRuMLB5goQyCO2EKv3hBkb77Ong0] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:05][pXcIaQ93sLx5XH9NJYpbb3CDqVtMhT40] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:10][IFedJb6OZwUaV5dlhFodoXk56SNk7RLE] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:14][wyK42WyxaF5DR7J4O61h4p7Pud85VK2g] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:15][FL7HERldD93pRYdrwG0xUMNo1TFpWpuI] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:08:11][FL7HERldD93pRYdrwG0xUMNo1TFpWpuI] Processed:  App\Jobs\ParseUserIP
[2018-08-18 20:08:11][EIUznJysjWbOt5MlzmMJVsan2nnD9XgK] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:08:51][EIUznJysjWbOt5MlzmMJVsan2nnD9XgK] Processed:  App\Jobs\ParseUserIP
[2018-08-18 20:08:51][ZTlzghKI7vPTIcNodu0yMwSDTcK5PsJi] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:09:04][ZTlzghKI7vPTIcNodu0yMwSDTcK5PsJi] Processed:  App\Jobs\ParseUserIP

當佇列處理器開始處理某個任務時就會輸出一條 Processing，當執行完畢時會輸出 Processed，當有很多個任務在同時執行時，我們可以根據中括號裡面的那個字串（即任務 ID）來區別不同的任務。

仔細觀察上面的日誌，可以發現 ParseUserIP 這個任務耗時比較長，比如 ID 為 FL7HERldD93pRYdrwG0xUMNo1TFpWpuI 的任務，開始執行的時間是 20:07:15，而結束時間是 20:08:11，花了將近一分鐘的時間。持續往下翻可以發現有大量的 ParseUserIP 任務出現長耗時的情況，而且一直持續，耗時 1 分鐘以上的不在少數。

於是我檢視了一下這個任務的程式碼，是呼叫淘寶的 IP 介面來查詢使用者 IP 歸屬地：

$ret = (new \GuzzleHttp\Client())->get('http://ip.taobao.com/service/getIpInfo.php?'.http_build_query(['ip' => $ip]));

之前這個介面都是秒回，現在這種情況應該是淘寶的這個介面本身出現了不穩定的情況。

這下有點明白問題出現在哪裡了，由於每次使用者登入都會觸發 ParseUserIP 這個任務，所以系統裡一直有大量的 ParseUserIP 任務待處理，在淘寶介面沒有出現不穩定之前，這些任務幾乎都是瞬間完成，因此一切正常。

而當淘寶介面開始不穩定，返回資料的時間從秒級變成分鐘級，ParseUserIP 任務就開始大量積壓，而 Laravel 的佇列處理器是按照入佇列的時間逐個去處理非同步任務的，因此即使我們在晚上 8 點就將推送任務存入 Redis，也需要等待佇列處理將之前積壓的 ParseUserIP 任務全部完成才會開始被處理。

呼叫 Http 介面不會大量佔用 CPU 和記憶體資源，這也解釋了為什麼伺服器負載不高。

解決方案

找到問題之後，解決起來就很簡單了：

  1. 呼叫淘寶介面時設定一個超時時間，比如 3 秒；
  2. 新增本地 IP 解析邏輯，當通過淘寶介面解析失敗時使用本地解析；
  3. 修改 Supervisor 的配置，將 4 個佇列處理器調整為 8 個；
  4. 排查所有涉及呼叫 Http 介面的程式碼，強制加上超時時間。
本作品採用《CC 協議》，轉載必須註明作者和本文連結

相關文章