751
技術社區[雲棲]
記 php-fpm 重啟導致的 程序執行中斷問題
背景和初步排查
- 訂單業務對賬時報警了，有筆訂單在我們自己的mongo庫裏沒有找到
- 業務接口
/3/xx/vgift/send調用支付網關sendPresent接口完成送禮， 之後寫mongo，但是php error log 裏卻查不到任何mongo異常日誌 - 寫mongo沒有異常，但是庫裏卻沒記錄； 推斷隻有2個可能，1是error log 丟日誌了。2是程序執行過程中操作完sendPresent後down掉了，導致沒寫入mongo
- 第一個情況工作多年的經驗來看應該不至於，那就先根據第二種情況繼續查吧
- 那就去看下php-fpm 的日誌，看對應的時間點有沒有什麼異常
[wu.daolin@web-game001.m6~]$ 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 12583
[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 執行了重啟任務，而且這個點發生很可能是個定時任務， 確認果然是這樣 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.
總結原因
-
/3/sdk/vgift/send裏 執行完sendPresent這個動作後 ， 還沒來得及寫mongo庫， php-fpm就剛好被terminate了，.... 真是剛好趕上了
替代方案
- 雖然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感覺功能重複了,根本沒必要定時重啟了， 我還是選 graceful stop(SIGQUIT) 吧
答sa提問
-QUIT 是否正常還不清楚，但現在的默認 -TERM 是立即停掉php 進程 是肯定不正常的呢； 對於已經建立好的連接，nginx error log 是 “104: Connection reset by peer”； 準備去連的是“111: Connection refused”； 這個看下現在的nginx error log 能對應的上
“111: Connection refused” 是還好的，連不上而已，稍後重試就可以；“104: Connection reset by peer” 這個就有可能有問題，我理解的意思是連接已經建好了，php突然中斷了，然後發了個RST分節給nginx出現的； 這個情況就表示當前請求可能隻執行了一半動作，還有動作沒執行完，這可能就造成丟數據了。。。比如我那個wiki描述的那個bug
reload 那個其實就是 -USR2信號，這個bug看起來還沒解決。。。不過-USR2 應該說是偶現，但 -TERM 肯定是必現
現在部署代碼隻是部署代碼+清理opcache和yac緩存， 不對php-fpm進程做操作
php-fpm 會自己對worker進程處理的請求數計數，達到一定數量就幹掉再重新拉一個； 所以worker進程應該沒有什麼內存泄露的問題； manager 進程就不清楚了，但我想概率應該是極其低的。這個適不適用感覺很難去證偽啊。。。
所以要不找3台機器， 一台用 -QUIT， 一台用 -USR2, 一台去掉這個定時任務；先觀察下
參考文檔
最後更新：2017-10-25 17:04:31