在docker以FPM-PHP運行php，慢日志導致的BUG分析

本文轉載自查看原文 2016-09-23 10:26 2621 fpm/ ptrace/ php/ SIGCONT/ docker

問題描述：

最近將IOS書城容器化，切換流量后。正常的業務測試了一般，都沒發現問題。線上的錯誤監控系統也沒有報警，以為遷移工作又告一段落了，暗暗的松了一口氣。緊接着，報警郵件來了，查看發現是一個蘋果支付相關接口調用的curl錯誤，錯誤碼為"56"，錯誤描述為：“Failure with receiving network data”接收網絡數據失敗。

機器 : 192.168.1.1
當前URL : /xxx/recharge/apple?xxxxxxxxxxxxx
接口URL : http://192.168.1.2:18000/third/apple/pay
錯誤信息 : Failure with receiving network data.
錯誤碼 : 56
type : curl
時間 : 2016-09-19 22:09:37 +0800 從09-19 21:20:15到09-19 22:09:38共計錯誤：11

問題分析：

整體的業務流程：用戶使用蘋果支付，客戶端拿到用戶支付后用戶返回的code，傳給php，php 使用curl post提交給用戶中心，用戶中心拿到code后請去蘋果支付的接口驗證是否合法。

懷疑方向：

1、code有超過4000個字節長度，而curl post提交超過1024個字節后，會發送100-continue，將請求分為2步。

2、書城服務器與接口服務器之間的網絡問題

3、libcurl的BUG（PHP這邊的HTTP Clinet使用的libcurl庫封裝的）

4、php7存在相關的bug

5、docker當前版本存在bug

懷疑驗證：

1、通過本地向用戶中心支付接口發起請求，打印頭信息，頭信息確實返回了兩次，第一次為"100-continue"。鳥哥在官網的文章中提過類似問題，在curl代碼中增加設置項，將"Expect"設為空，然后測試，發現不會分步驟了，本地測試代碼沒有報錯。然后提交上線。

1 curl_setopt($ch, CURLOPT_HTTPHEADER, array('Expect:'));

curl設置Expect

發現錯誤並沒有解決，報錯依然存在。還原之前的代碼，排除掉懷疑1。

2、將抓網卡數據包的命令給運維，讓其幫忙加一下任務，監聽網卡流量信息。當發現問題后，停掉腳本，發給我們。我們根據錯誤郵件報警時間與網卡流量中的記錄進行對照

找出具體的數據包信息。命令如下：

1 tcpdump -i team0 host 192.168.7.154 and port 29000 -w /tmp/apple_pay.cap

tcpdump 抓包

后我就等着發報警郵件，發現報警之后，讓運維終止掉腳本，然后通過"wireshark"分析，對比一下正常的和有問題的：

（正常情況）

(有問題的)

可以從序列號11-12看到有問題的tcp連接在超過2秒后，client端（1.1）自動發送了FIN。服務端進行了確認，但是序列號14看到，大概4s后服務端才返回數據，這個時候客戶端已經不接受數據了。

這個時候又引入了一個懷疑點，跟書城服務器的網絡參數配置有關。

3、通過命令"sysctl -a | grep tcp" 查看linux內核配置的tcp相關的參數。經過各種查資料發現沒有一個是跟當前2秒中斷對應的上的。排除掉 懷疑2

4、php請求apple/pay接口是這設置的10S超時，為什么2S就返回了呢，會不會是libcurl定時器的BUG呢？

帶着問題繼續找答案，php一般請求服務接口代碼如下。

1 $ch = curl_init();//初始化curl
2 curl_setopt($ch, CURLOPT_URL, "http://192.168.7.154:29000/third/apple/pay");//設置curl請求URL
3 curl_setopt($ch, CURLOPT_TIMEOUT, 10);//設置超時
4 curl_setopt($ch, CURLOPT_POSTFIELDS, array(k=>v));//設置POST請求的數據
5 $data = curl_exec($ch);//執行請求，並獲取響應數據
6 curl_close($ch); //關閉

php curl請求設置

繼續深入到 curl_exec php源碼中 https://github.com/php/php-src/blob/2a71140d54e956f11acbe33f2681d27086874d2e/ext/curl/interface.c#L3016

 1 PHP_FUNCTION(curl_exec)
 2 {
 3     CURLcode    error;
 4     zval        *zid;
 5     php_curl    *ch;
 6     if (zend_parse_parameters(ZEND_NUM_ARGS(), "r", &zid) == FAILURE) {
 7         return;
 8     }
 9     if ((ch = (php_curl*)zend_fetch_resource(Z_RES_P(zid), le_curl_name, le_curl)) == NULL) {
10         RETURN_FALSE;
11     }
12     _php_curl_verify_handlers(ch, 1);
13     _php_curl_cleanup_handle(ch);
14     error = curl_easy_perform(ch->cp);
15     ........................
16     ........................
17     ........................
18 }

php 內核中curl_exec的實現

發現PHP的curl_exec函數最終調用 libcurl中的curl_easy_perform函數，線上服務的libcurl是7.29.0版本，繼續看libcurl源碼

ibcurl 提供的C函數API大概如下，可以看出來php的curl只是對libcurl做了一個簡單的封裝。libcurl API列表

1 //libcurl 提供的C函數API大概如下
2 curl = curl_easy_init(); 
3 curl_easy_setopt(curl, CURLOPT_URL, "http://xxx/");
4 res = curl_easy_perform(curl); 
5 curl_easy_cleanup(curl);

libcurl 調用的基本函數

curl 設置定時器的流程大概如下：

curl_easy_perform curl_multi_wait Curl_poll

 1 int Curl_wait_ms(int timeout_ms)
 2 {
 3   if(!timeout_ms)
 4     return 0;
 5   if(timeout_ms < 0) {
 6     SET_SOCKERRNO(EINVAL);
 7     return -1;
 8   }
 9   pending_ms = timeout_ms;
10   initial_tv = curlx_tvnow();
11   do {
12 #if defined(HAVE_POLL_FINE)
13     r = poll(NULL, 0, pending_ms);
14 #else
15     pending_tv.tv_sec = pending_ms / 1000;
16     pending_tv.tv_usec = (pending_ms % 1000) * 1000;
17     r = select(0, NULL, NULL, NULL, &pending_tv);
18 #endif /* HAVE_POLL_FINE */
19     if(r != -1)
20       break;
21     error = SOCKERRNO;
22     if(error && error_not_EINTR)
23       break;
24     pending_ms = timeout_ms - elapsed_ms;
25     if(pending_ms <= 0)
26       break;
27   } while(r == -1);
28    
29   if(r)
30     r = -1;
31   return r;
32 }

libcurl 中的Curl_wait_ms函數

整個libcurl的超時機制都沒有問題，基本排除懷疑3。

5、難道是PHP的BUG,最新剛剛升級到PHP7。

在docker里面測試 s.php測試代碼如下：

1 sleep(5);
2 echo "asdadadasdsad";

php設置sleep

以http的方式請求這個php

[root@BJ-M5-PHP-7-225 apad]# time curl "http://127.0.0.1:8046/s.php"
asdadadasdsad
real    0m2.010s
user    0m0.004s
sys     0m0.005s

很奇怪的問題出現了 real 0m2.010s ，明明是sleep 5 秒為啥只執行了2 秒就結束了，而且還返回了數據。

php s.php 執行正常

php -S 127.0.0.1:8046（php內置的web server）執行正常

python以web server的方式

 1 #!/usr/bin/env python
 2 # -*- coding: utf-8 -*-
 3 import tornado.httpserver
 4 import tornado.ioloop
 5 import tornado.options
 6 import tornado.web
 7 import time
 8 from tornado.options import define, options
 9 define("port", default=8888, help="run on the given port", type=int)
10 class MainHandler(tornado.web.RequestHandler):
11     def get(self):
12         time.sleep(5)
13         self.write("Hello, world")
14  
15 def main():
16     tornado.options.parse_command_line()
17     application = tornado.web.Application([
18         (r"/", MainHandler),
19     ])
20     http_server = tornado.httpserver.HTTPServer(application)
21     http_server.listen(options.port)
22     tornado.ioloop.IOLoop.current().start()
23  
24 if __name__ == "__main__":
25     main()

View Code

執行正常

nginx sleep 5 執行正常

1   location /sub1 {
2     echo_sleep 5;
3     echo "hello world";
4 }

View Code

上面測試均在docker 1.10.3容量里面進行，在物理機器上並無此問題。經過上面的測試發現，在docker 1.10.3只有以PHP-FPM運行時，才會出現此問題。

猜想可能是fpm的問題，看了一下php-fpm.conf的配置信息。發現了request_slowlog_timeout=2s，重大發現，唯一一個2s有點重合的點。立即把修改了10s，結果測試sleep 5 正常了。

request_slowlog_timeout是記錄FPM方式執行php的慢日志時間，超過設置的時間就會有慢日志記錄。很好奇為什么超過request_slowlog_timeout執行的php會出現問題，物理機為什么是正常？帶着問題繼續看FPM。

經過分析fpm源碼，發現了使用request_slowlog_timeout的流程。在fpm work 進程處理請求時，master進程做健康檢查，其中就有slowlog_timeout。

fpm_pctl_check_request_timeout源碼

1 if (child->slow_logged.tv_sec == 0 && slowlog_timeout &&
2             proc.request_stage == FPM_REQUEST_EXECUTING && tv.tv_sec >= slowlog_timeout) {
3          
4     str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
5     child->slow_logged = proc.accepted;
6     child->tracer = fpm_php_trace;//記錄執行慢的php棧調用的回調函數
7     fpm_trace_signal(child->pid);//調用ptrace函數，追蹤進程
8     ....................
9 }

fpm_pctl_check_request_timeout 慢日志記錄

pm_trace_signal源碼

 1 //開始追蹤進程
 2 int fpm_trace_signal(pid_t pid){
 3     if (0 > ptrace(PTRACE_ATTACH, pid, 0, 0)) {
 4         zlog(ZLOG_SYSERROR, "failed to ptrace(ATTACH) child %d", pid);
 5         return -1;
 6     }
 7     return 0;
 8 }
 9 //關閉追蹤
10 int fpm_trace_close(pid_t pid){
11     if (0 > ptrace(PTRACE_DETACH, pid, (void *) 1, 0)) {
12         zlog(ZLOG_SYSERROR, "failed to ptrace(DETACH) child %d", pid);
13         return -1;
14     }
15     traced_pid = 0;
16     return 0;
17 }
18 //獲取棧調用信息
19 int fpm_trace_get_long(long addr, long *data){
20     errno = 0;
21     *data = ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0);
22     if (errno) {
23         zlog(ZLOG_SYSERROR, "failed to ptrace(PEEKDATA) pid %d", traced_pid);
24         return -1;
25     }
26     return 0;
27 }

獲取php棧調用的函數

關鍵性函數來了ptrace

ptrace解釋:

ptrace 提供了一種機制使得父進程可以觀察和控制子進程的執行過程，ptrace 還可以檢查和修改該子進程的可執行文件在內存中的鏡像及該子進程所使用的寄存器中的值。這種用法通常來說，主要用於實現對進程插斷點和跟蹤子進程的系統調用。是的你沒有想錯，strace、gdb就是通過它實現的。

為啥說ptrace是關鍵性函數呢？看如下兩種strace跟蹤系統調用。

 1 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 2 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
 3 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 4 nanosleep({5, 0}, {2, 499689873}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
 5 --- SIGSTOP {si_signo=SIGSTOP, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 6 --- stopped by SIGSTOP ---
 7 --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 8 restart_syscall(<... resuming interrupted call ...>) = 0  //請注意這行
 9 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
11 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

正常的strace追蹤

 1 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 2 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
 3 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 4 nanosleep({5, 0}, {2, 499689873}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
 5 --- SIGSTOP {si_signo=SIGSTOP, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 6 --- stopped by SIGSTOP ---
 7 --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1879, si_uid=0} ---
 8 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 9 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fc8f5ee7670}, 8) = 0
10 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

異常的strace追蹤，在docker 1.10.3中

看出來區別沒？注意正常strace追蹤的第8行，restart_syscall(<... resuming interrupted call ...>)，重新恢復中斷的調用。

PHP的慢日志實現方式是這樣的：

1、調用ptrace的PTRACE_ATTACH命令，master會進程通過向子進程發送SIGSTOP信號，此時子進程會變成TASK_TRACED狀態，被追蹤狀態。

即：ptrace(PTRACE_ATTACH, pid, 0, 0)); 這行代碼

2、調用ptrace的PTRACE_PEEKDATA命令，來獲取子進程的棧調用信息。

即：ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0); 這行代碼

3、調用ptrace的PTRACE_DETACH命令，結束追蹤。master會進程通過向子進程發送 PTRACE_CONT信號，此時子進程會變成TASK_RUNING狀態。

即：ptrace(PTRACE_DETACH, pid,(void *) 1, 0); 這行代碼

    問題在於 docker 1.10.3 中 收到 SIGCONT信號后，並沒有執行restart_syscall，恢復進程執行的上下文，改變了進程運行時上下文。

    因此子進程受到SIGSTOP到SIGCONT這段時間內，正在被執行的函數由於運行時上下文導致執行異常。后面的代碼繼續執行。

sleep(5);
echo "asdadadasdsad";

php中的這兩行代碼，在執行到sleep(5)的過程中，觸發了fpm的慢日志記錄，進程被暫停，等到恢復時，由於docker 1.10.3BUG，進程上下文被改變導致sleep執行出問題，但是后面的echo 繼續執行。

6、將docker版本從1.10.3升級到1.11.2，通過步驟5的測試，發現問題不存在。

結論：

1、罪魁禍首是docker1.10.3的SIGCONT信號處理BUG，而且fpm slowlog配置"request_slowlog_timeout=2s"調用了ptrace正好發送了SIGCONT信號。

2、php curl接口之前設置的超時時間為10秒，而由於支付接口請求蘋果支付那邊的時間比較長，會出現很多超時現象

問題解決辦法：

1、目前先通過關閉fpm的slowlog來解決（臨時）

2、后續會全量升級docker版本（永久）

免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。

猜您在找 PHP性能調優，PHP慢日志---善用php-fpm的慢執行日志slow log，分析php性能問題 php-fpm 慢日志查詢 PHP-FPM 開啟慢日志記錄 php-fpm開啟慢查詢日志 php-fpm開啟慢日志 php-fpm的一次慢執行日志slow log Docker搭建nginx+php-fpm運行環境 php-fpm運行原理 [PHP] PHP-FPM的access日志error日志和slow日志 MySQL慢日志分析慢SQL