事情的背景
- 禮物訂單對賬時報警了，有筆訂單在我們自己的mongo庫裡沒有找到
- php api 介面
/3/xx/vgift/send呼叫禮物系統sendPresent介面完成送禮， 之後寫mongo - 但是庫裡現在沒記錄，而且 php error log 也查不到任何mongo異常日誌
- 推初步斷只有2個可能
1是error log 丟日誌了。 2是程式執行過程中操作完sendPresent後down掉了，導致沒寫入mongo
- 第一個情況工作多年的經驗來看應該不至於，那就先根據第二種情況進行排查
排查
- 先看下 php-fpm 的日誌，看對應的時間點有沒有什麼異常，發現有線索
[wu.daolin@*****~]$ grep "2017 05:28" /var/log/php-fpm.log
[25-Jun-2017 05:28:01] NOTICE: Terminating ...
複製程式碼熟悉下 php-fpm 的管理
php-fpm 是通過 php-fpm這個命令進行管理的，我們先看下這個命令
man php-fpm
這裡有提到，php-fpm then responds to several POSIX signals php-fpm 會對下面幾個訊號作（自己的）處理
- SIGINT, SIGTERM: immediate termination
- SIGQUIT: graceful stop
- SIGUSR1: re-open log file
- SIGUSR2: graceful reload of all workers + reload of fpm conf/binary
動手驗證下
sudo kill -QUIT {php-fpm-pid}
[26-Jun-2017 13:58:22] NOTICE: Finishing ...
[26-Jun-2017 13:58:22] NOTICE: exiting, bye-bye!
複製程式碼sudo kill -TERM {php-fpm-pid}
[26-Jun-2017 13:59:21] NOTICE: Terminating ...
[26-Jun-2017 13:59:21] NOTICE: exiting, bye-bye!
複製程式碼sudo kill -USR2 {php-fpm-pid}
[26-Jun-2017 14:00:48] NOTICE: Reloading in progress ...
[26-Jun-2017 14:00:48] NOTICE: reloading: execvp("/usr/sbin/php-fpm", {"/usr/sbin/php-fpm", "--daemonize"})
[26-Jun-2017 14:00:48] NOTICE: using inherited socket fd=8, "10.30.60.87:9000"
[26-Jun-2017 14:00:48] NOTICE: using inherited socket fd=8, "10.30.60.87:9000"
[26-Jun-2017 14:00:48] NOTICE: fpm is running, pid 12696
[26-Jun-2017 14:00:48] NOTICE: ready to handle connections
複製程式碼從以上驗證結果推斷
在 05:28:01這個時間有人給php-fpm 傳送了SIGTERM訊號。 在這個點發生的很可能是個定時任務， 查了下crontab 果然是這樣 28 5 * * * root /etc/init.d/php-fpm restart> /dev/null
看下我們的 php-fpm 管理
- init script 是 /etc/init.d/php-fpm
- 其中stop 是
killproc -p ${pidfile} php-fpm, 顯然從日誌結果來個是kill -TERM. 文件裡也說了預設訊號就是TERMkillproc sends signals to all processes that use the specified executable. If no signal name is specified, the signal SIGTERM is sent.
看下這個情況下nginx的反應
原因
- 業務請求時執行完
sendPresent這個動作後， php-fpm就剛好被terminate掉了, 導致訂單沒能寫入mongo
後續替代方案分析
- 雖然php-fpm 沒有解釋
terminate跟graceful stop的具體含義， 但猜的話前者是直接就終止程式的執行了，後者可能是溫柔點，把處理中的請求裡的所有操作都執行完再殺死。。。 - 首先
SIGTERMterminate掉php 工作程式太粗暴了，應該要改一下比較好 - 改成
SIGUSER2reload 方式 - 改成
SIGQUIT方式 ,把killproc -p ${pidfile} php-fpm這句 改成killproc -p ${pidfile} php-fpm -QUIT - php-fpm 的worker 是計數N次後就會自動殺掉重新拉一個，如果用reload感覺功能重複了,根本沒必要定時重啟了， 我還是選 SIGQUIT(graceful stop )試試吧
- 當然還有個問題時，為啥要配置個定時重啟，將上面的內容發給sa看了
與sa 的問答
sa 說了3點意見
-
建議看下 -QUIT 時，Nginx的狀態碼是否正常？另外在某種情況下，可能會造成 PHP-FPM 程式退出時間比較長，會影響部署嗎？
-
用
reload(SIGUSER2)而不是用SIGTERM停掉再啟動. 我們之前的測試結果看 reload 之後，nginx會報 502，並不 graceful stop。建議做好測試確認，包括部署php程式碼時是不是 reload？ Bug #60961 Graceful Restart (USR2) isn't very graceful -
php-fpm每天定時重啟指令碼 這個定時指令碼大概是在2012年部署的，當時是擔心 PHP-FPM 存在記憶體洩漏的情況而新增的。到現在是不是還適用？建議找一臺機器關掉定時指令碼觀察一段較長時間看看。
我的回覆
SIGQUIT是否正常還不清楚，但現在的預設SIGTERM是立即停掉php 程式是肯定不正常的。
從nginx error log 看，對於nginx 和 php-fpm已經建立好的連線，錯誤是 “104: Connection reset by peer”； 準備去連的是“111: Connection refused”；
-
“111: Connection refused” 是還可以接受的，連不上而已，使用者稍後重試就可以；“104: Connection reset by peer” 這個就很難接受，這個錯我的理解是
連線已經建好了，php突然terminate了，然後發了個RST分節給nginx；這意味當前請求可能只執行了部分動作，還有動作沒執行，這可能就造成丟資料了。。。比如我們開頭遇到的這個問題 -
reload 那個其實就是 -USR2訊號，這個bug看起來還沒解決。。。不過-USR2 應該說是偶現terminate，但 -TERM 是必現terminate
-
現在程式碼部署是
同步程式碼+清理opcache和yac快取， 不對php-fpm程式做操作 -
php-fpm 會自己對worker程式處理的請求數計數，達到一定數量就幹掉再重新拉一個； 所以worker程式應該沒有什麼記憶體洩露的問題； manager 程式就不清楚了，但我想概率應該是極其低的。這個感覺很難去證偽啊。。。
-
所以要不找3臺機器， 一臺用 -QUIT， 一臺用 -USR2, 一臺去掉這個定時任務；先觀察下
-
sa 回覆可以，我們自己看著辦
後來
- 改成 SIGQUIT 訊號nginx裡還是有
104: Connection reset by peer， 看來手冊裡說SIGQUIT: graceful stop也不能保證一次請求裡的所有動作都執行完啊 - 最終結果
去掉這個定時重啟php-fpm 的任務, 已經3個多月了，沒發現問題，oh yeah~