## 背景 >最近在提供後臺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服務，從與上游服務開始建立連線，到接收完響應返回的最後一個位元組，所經過的時間。單位為秒  程式真正的執行時間 = $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 以及 gd