API返回延遲,FPM重啟後恢復之後又重現 問題解決方案

糖糖果發表於2020-07-28
API

背景

最近在提供後臺API時,提供了一個簡單邏輯的介面
部署在測試環境，自測沒問題，提交測試
突然有一天,介面響應延遲嚴重，幾乎每次都是3-4秒返回
這對於一個介面來說，肯定是有問題的
於是便有了以下的方法嘗試

重啟FPM

  • 最開始以為不是什麼大問題，猜想可能是fpm問題
    畢竟測試環境，部署程式碼繁多
  • 重啟後，介面響應正常，可不一會就又復現

重新分析定位問題

  • 經過幾次的嘗試後，發現問題其實沒有那麼簡單
  • 重啟fpm後，過了不到幾秒，問題依然復現
  • 編寫簡單的php檔案，無複雜邏輯，只輸出字串，問題復現
  • 命令列執行檔案，無此問題
  • 經過以上嘗試，確認是FPM的問題
    或者PHP的初始化解析執行的問題，當時想是不是有特定的模組載入
    經過php -m 檢視，無特殊模組(其實應該仔細看看,所以才繞了彎路)

日誌定位

有了上面的分析，最先想到的是利用日誌檢視問題

檢視nginx日誌

  nginx 日誌 格式，新增詳細的 各個時間段的相應

  log_format main '$remote_addr [$host] - $remote_user [$time_local] $request upstream_response_time: $upstream_response_time
   request_time: $request_time upstream_connect_time: $upstream_connect_time upstream_header_time:$upstream_header_time 
  $status $body_bytes_sent $http_referer $http_user_agent ';

  新增了 
        upstream_response_time
        upstream_connect_time
        upstream_header_time

  含義如下:
        request_time
              nginx服務，從發起請求的客戶端獲取到第一個位元組開始，到返回給客戶端最後一個位元組，日誌寫入檔案後，所經過的時間。單位為秒。
        upstream_connect_time
              nginx服務，從與上游服務開始建立連線，到連線建立成功，所經過的時間。單位為秒。
        upstream_header_time
              nginx服務，從與上游服務開始建立連線，到接收到響應返回頭的第一個位元組，所經過的時間。單位為秒。
        upstream_response_time
              nginx服務，從與上游服務開始建立連線，到接收完響應返回的最後一個位元組，所經過的時間。單位為秒
		
        ![](https://img2020.cnblogs.com/blog/385704/202007/385704-20200728162028181-1944819290.jpg
        [參考連結](https://juejin.im/post/5d26eb16f265da1bd522f8d6)

  程式真正的執行時間 = $upstream_header_time - $upstream_connect_time
  $request_time 中包含了資料返回時間
  $request_time 中包含了日誌列印的時間

  nginx 日誌顯示
  xxx [xxx] - - [11/Jul/2020:13:36:45 +0000] POST /xxx/xxx HTTP/1.1 upstream_response_time: 3.048 request_time: 3.048 upstream_connect_time: 0.000 upstream_header_time:3.048 200 98 - Dalvik/2.1.0 (Linux; U; Android 8.1.0; vivo 1808 Build/O11019)
  從中可以看出確實是 上游服務FPM 返回延遲了

配置 FPM 慢日誌

lowlog = /xxx/www-slow.log request_slowlog_timeout = 1s

發現 慢日誌中，並沒有記錄
於是懷疑是否 日誌檔案許可權有問題，修改後依然未寫入
想到用sleep的方式，寫入慢日誌，成功寫入

現象就是 配置了1秒的FPM慢日誌，介面響應超過1s，但沒有寫入慢日誌
那就說明 PHP 程式執行完成後，又做了什麼處理，導致了延遲
或者 其他的配置問題

檔案描述符

網上搜尋, 可能是 檔案的開啟數量有限制, 並沒有做優化
於是 檢視對應的配置
nginx 配置檔案 worker_rlimit_nofile
ulimit -n
是做了優化的的
也並不是網上所說的問題

思考

  • 所有的PHP程式響應都有延遲，超過3s左右
    所以並不是個例，和其他的如mysql redis 連線沒關係
  • 突然間出現的，原來是沒問題的，應該是近期做了更改
    但由於測試環境，東西太多，一時也找不到是什麼改動
  • 命令列模式下，沒有延遲，所以和FPM有關
    而重複FPM後,幾秒內正常,後又復現
    一直以為是FPM配置有什麼問題,目前看並不是
  • 所以肯定是 程式處理完成後，又做了什麼，導致了延遲
    那有什麼辦法可以追蹤程式碼的執行嗎
    對於php而言，xhprof擴充套件 是可以很好的展示一個流程中的耗時
    而且還有對應的圖片展示(需要安裝擴充套件)，但還需要安裝
    於是就有了下面的方法

strace除錯跟蹤

簡單來說，strace是用來跟蹤程式內的系統呼叫和接受的訊號。
對程式除錯很有幫助

  • 於是,來除錯FPM的程式，看看都做了哪些呼叫
    strace -t -f $(pidof php-fpm| sed 's/\([0-9]*\)/\-p \1/g') -epoll -o /tmp/strace.txt
    開啟檔案
    12406 06:55:13 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLIN}])
    12406 06:55:13 poll([{fd=6, events=POLLOUT|POLLWRNORM}], 1, 10000) = 1 ([{fd=6, revents=POLLOUT|POLLWRNORM|POLLERR|POLLHUP}])
    12405 06:55:16 --- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=12401, si_uid=0} ---
    12405 06:55:16 +++ exited with 0 +++
    12401 06:55:16 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12405, si_status=0, si_utime=0, si_stime=0} ---`
  • 通過以上資訊，在 06:55:13後，確實有超過3秒的時間，是 fd=6 導致的, 那 fd=6 是什麼
    可通過 lsof -p pid 的方式檢視
    但 程式id 12405 退出了
    就是說，由於FPM的動態啟動程式的配置，一個程式退出後，會重新生成程式，已達到配置的程式數
    所以 一邊列印除錯資訊，一邊輸出 工作pid的 檔案資訊
  • lsof -p 12408
    php-fpm 12408 apache 5u IPv4 1203792101 0t0 TCP localhost:cslistener->localhost:22384 (ESTABLISHED)
    php-fpm 12408 apache 6u IPv4 1203794606 0t0 TCP xx.com:28866->ip-10-66-100-169.ec2.internal:9411 (SYN_SENT)

此時，原因終於找到了,在每次結束後，又請求了某個ip 9411埠的服務
可以看到tcp狀態是 SYN_SENT，雖然已發出連線請求，但對應沒回應，並不是ESTABLISHED狀態
說明是對應請求機器的問題

於是去檢視此ip對應機器,原來確實有此機器，但不知什麼時候起，此機器已下架了
導致了這個問題，此刻想到了為什麼突然之間介面就有延遲了

問題修復

既然確認了是連線了某個服務導致的問題，對應的php配置檔案應該有配置
於是 找到 所有模組配置檔案ini路徑，搜尋ip
發現是 其 molten 擴充套件配置

molten 擴充套件是一個全鏈路追蹤的工具
molten追蹤php核心呼叫庫執行時資訊並且按照zipkin/optracing格式輸出資訊。
可以追蹤curl,pdo,mysqli,redis,mongodb,memcached 這麼多的執行資訊。

去掉此擴充套件載入，重啟FPM後，介面響應正常

總結

  • 問題出現的時候，最直觀的方式應該是日誌，通過檢視日誌，可以解決大部分問題
  • 當日志解決不了的問題，如何除錯，就成了問題解決的關鍵
    strace ltrace 以及 gdb 除錯

相關文章