記一次 PHP-FPM 可以建立慢日誌，但是卻不能寫入內容的折騰過程

reggie發表於2019-05-20
PHP

說來慚愧，公司的伺服器環境用了那麼久連PHP的慢日誌都沒，然後一通設定，最後發現慢日誌檔案是生成了，但是卻沒有內容寫入。難道效能這麼高的麼？這肯定不可能的啊，然後給程式碼加入 sleep(second) 還是不生效。就知道肯定要折騰了！

環境介紹

首先公司所有的專案都是部署在 Docker 中的(自己做的映象),然後都是使用 Nginx 和 PHP-FPM 通訊來執行 PHP 內容，大概環境就這樣。

名詞解釋

這裡會有幾個名詞 可以看我這篇部落格 相關名詞解釋。
沒空看就算了 在簡單說下：

CGI: 是一個協議，規定了Web伺服器和後端語言的互動。但是效能差點，每個請求都會fork一個新的程式。\
FastCGI: 也是一個協議，是CGI的升級版，可以在一個程式內處理多個請求\
FPM：FastCGI程式管理器，是一個實現了FastCGI協議的工具\
PHP-FPM: 是一個PHP的程式管理器，專門給PHP使用的FPM工具\

Nginx與PHP的通訊

首先Nginx並不是直接和PHP進行通訊的，而是透過PHP-FPM。Nginx不僅僅是一個強大的Web伺服器，也是一個強大的代理伺服器，提供了很多請求協議的代理。比如Http協議還有FastCgi協議等。

當請求進入到Nginx中，Nginx提供了一個 FastCgi模組 來把Http請求對映為對應的 Fastcgi 請求。該模組提供了 fastcgi_param 指定來完成對映關係。它的主要作用就是把Nginx中的變數翻譯成PHP中能夠理解的變數。 一般該檔案是在Nginx的安裝目錄下，我的內容如下:

/etc/nginx # cat /etc/nginx/fastcgi_params 

fastcgi_param  QUERY_STRING       $query_string;
fastcgi_param  REQUEST_METHOD     $request_method;
fastcgi_param  CONTENT_TYPE       $content_type;
fastcgi_param  CONTENT_LENGTH     $content_length;
fastcgi_param  SCRIPT_NAME        $fastcgi_script_name;
fastcgi_param  REQUEST_URI        $request_uri;
fastcgi_param  DOCUMENT_URI       $document_uri;
fastcgi_param  DOCUMENT_ROOT      $document_root;
fastcgi_param  SERVER_PROTOCOL    $server_protocol;
fastcgi_param  REQUEST_SCHEME     $scheme;
fastcgi_param  HTTPS              $https if_not_empty;
fastcgi_param  GATEWAY_INTERFACE  CGI/1.1;
fastcgi_param  SERVER_SOFTWARE    nginx/$nginx_version;

fastcgi_param  REMOTE_ADDR        $remote_addr;
fastcgi_param  REMOTE_PORT        $remote_port;
fastcgi_param  SERVER_ADDR        $server_addr;
fastcgi_param  SERVER_PORT        $server_port;
fastcgi_param  SERVER_NAME        $server_name;

# PHP only, required if PHP was built with --enable-force-cgi-redirect
fastcgi_param  REDIRECT_STATUS    200;

還有一個重要的指令 fastcgi_pass,用來指定FPM程式監聽的地址，Nginx會把所有的PHP請求對映成fastcgi請求，然後傳送到這個地址上。 我的配置檔案 nginx.conf 中配置如下

location ~ \.php$ {
     fastcgi_split_path_info ^(.+\.php)(/.+)$;
     fastcgi_pass unix:/var/run/php/php7.1-fpm.sock;
     fastcgi_index index.php;
     include fastcgi_params;
     fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;

     fastcgi_intercept_errors off;
     fastcgi_buffer_size 16k;
     fastcgi_buffers 4 16k;
     fastcgi_connect_timeout 300;
     fastcgi_send_timeout 300;
     fastcgi_read_timeout 300;
 }

這個的意思是把所有的 .php 結尾的請求都交給fastcgi模組處理，然後把處理後的請求傳送給PHP-FPM，然後PHP-FPM把請求交給worker程式，worker程式載入PHP解析器執行PHP處理結果。 其中 fastcgi_pass unix:/var/run/php/php7.1-fpm.sock; 這一行用來指定fpm的地址。

其中Nginx和FPM的通訊有兩種方式：

1.使用unix socket:unix socket是一種終端，可以使同一臺作業系統上的兩個或多個程式進行資料通訊。這種方式需要再nginx配置檔案中填寫php-fpm的pid檔案位置，效率要比tcp socket高。

2.使用tcp socket:優點是可以跨伺服器，當nginx和php-fpm不在同一臺機器上時，只能使用這種方式

我的伺服器上因為 Nginx和PHP都是安裝在同一個容器中的所以使用的 unix sockert 通訊模式

總結：Nginx和PHP的通訊流程大概如下。

  • 客戶端傳送請求到Nginx
  • 載入 nginx.conf 檔案，把所有 .php 結尾的請求特殊處理
  • 載入FastCGI模組，完成請求引數的解析對映，生成FastCGI請求
  • 然後透過 fastcgi_pass 引數把 FastCGI 請求傳送給 PHP-FPM處理
  • PHP-FPM收到請求，分配給空閒worker子程式
  • worker子程式載入PHP解析器等 完成PHP執行獲取結果

PHP-FPM的執行原理

PHP-FPM是一種 master/worker 程式架構。首先會啟動一個master主程式，主要功能用來完成PHP環境的初始化，事件監聽，子程式狀態管理等等。然後會啟動若干worker子程式來處理PHP請求。

根據 PHP-FPM的配置檔案可以看到它有3種管理子程式的方式。

php-fpm-child-process

簡單介紹下3種模式：

static: 啟動時建立固定數量的子程式 可以透過 pm.max_children 來指定數量
dynamic: 子程式的數量會根據下面的幾個引數設定來確定，不過最少會保證一個子程式。

  • pm.max_children: 可以同時存在的最大子程式數量
  • pm.start_servers: 啟動時建立的子程式數
  • pm.min_spare_servers: 等待執行的最小數量，如果等待執行的程式數小於該值，這時就會建立一些子程式出來。（建議設定1，這樣就不會有多餘的空閒子程式）
  • pm.max_spare_servers: 等待執行的最大數量，如果等待執行的程式數大於該值，這時就會殺掉一些子程式。免得浪費資源

ondemand: 當啟動的時候不會建立子程式。當新的請求連線進來的時候才會建立子程式。可以使用下面的引數來設定

  • pm.max_children: 可以同時存在的最大子程式數量
  • pm.process_idle_timeout: 當一個等待執行的程式操作設定的這個秒數後將會被殺掉

master程式的工作流程

1.初始化CGI，註冊程式訊號初始化全域性變數。
2.完成PHP環境初始化。載入 php.ini解析配置檔案，載入PHP模組記錄函式符號表，載入zend擴充套件，設定禁用函式和類庫設定，註冊回收記憶體方法。
3.完成PHP-FPM初始化。載入並解析 php-fpm.conf 檔案，獲取程式相關引數，初始化程式池以及事件模型等。
4.處理子程式相關操作。fork子程式，進行事件監聽等。

worker程式工作流程

1.接收請求。這裡是不需要初始化PHP執行環境的。
2.處理請求。獲取請求內容註冊全域性變數($_GET,$_POST,$_SERVER 等)，然後根據請求資訊訪問對應的PHP檔案，然後將PHP指令碼檔案交給Zend引擎處理。
3.處理結果。在Zend引擎處理完畢後將會進行回撥，傳送響應內容，釋放記憶體等

PHP-FPM管理操作

首先找到你的php-fpm所在的目錄：find / -name php-fpm 注意名字，比如我的php-fpm其實名字是 php-fpm7

/etc/nginx # find / -name php-fpm7
/etc/init.d/php-fpm7
/etc/logrotate.d/php-fpm7
/usr/sbin/php-fpm7

1.測試php-fpm配置內容是否正確 使用 -t 引數， 還可以透過加 -c 指定 php.ini 檔案，透過 -y 指定 php-fpm.conf 檔案【注意：檔案路徑】

  • /usr/sbin/php-fpm7 -t
  • /usr/sbin/php-fpm7 -c /usr/local/php/etc/php.ini -y /usr/local/php/etc/php-fpm.conf -t

2.啟動php-fpm

  • /usr/sbin/php-fpm7

3.關閉php-fpm [fpm-master-pid] 是master主程式的id 或者你有php-fpm.pid檔案也行 cat /usr/local/php/var/run/php-fpm.pid

  • kill -INT fpm-master-pid

4.重啟php-fpm

  • kill -USR2 fpm-master-pid

5.使用 root 許可權啟動子程式 透過增加 -R 引數

  • /usr/sbin/php-fpm7 -c xxx/xxx/xxx/php.ini -y /xxx/xxx/xxx/php-fpm.conf -R

更多引數見 /usr/sbin/php-fpm7 -h

PHP-FPM慢日誌配置

關於PHP-FPM配置慢日誌的說明網上一大堆。反正搜什麼都是給你顯示怎麼配置的搜尋結果，真是夠了！

常規配置如下:

; 這裡是你的子程式的名字 這裡我寫的是 www123 你可以換成別的什麼 注意使用 [] 包起來
[www123]

; 程式的Unix使用者/組 設定
user = app
group = app

; 接收FastCGI請求的地址，這裡是可以是一個IPv4, IPv6 或者unix socket
listen = /run/php/php7.1-fpm.sock

; 設定 Unix Socket的 使用者/組/許可權
listen.owner = app
listen.group = app
listen.mode = 0666

; 設定子程式的管理方式 參考上面的科普
pm = dynamic
pm.max_children = 5
pm.start_servers = 2
pm.min_spare_servers = 1
pm.max_spare_servers = 3

; 這裡是重點 慢日誌slowlog的儲存位置和請求時間，超過這個時間的請求就會被記錄到慢日誌中
; 注意這裡的檔案目錄是需要先建立好的，具體的日誌檔案不需要提前建立好
; 這裡可以設定的時間可以是 秒(s), 分鐘(m), 小時(h) 和 天(d)
slowlog = /app/logs/my_slow_log/$pool.log.slow
request_slowlog_timeout = 1s

你可以不用把上面這些配置寫到 php-fpm.conf 檔案中，比如你可以建個 pool.d 資料夾，然後在 php-fpm.conf 中 透過 include=/etc/php/7.1/fpm/pool.d/*.conf 引入這些檔案(注意路徑不要直接copy我的)。如果你做了反向代理配置了很多個站點也可以寫多份這個檔案配置，改下子程式的名字 也就是一開頭的 www123 這樣你可以把不同的站點分開記錄。

這裡有一份詳細的配置檔案 可以參考下 www.conf

處理問題

上面是一些簡單的總結，具體的還有很多細節，有興趣的可以自己再去惡補下。下面回到開頭的問題上，在經過了一番準備工作後，本以為可以正常使用了，但是事實並非如此，發生了文章開頭的問題。慢日誌的slow-log檔案被建立了出來，但是卻沒有內容寫進去，十分詭異！(我給測試連線中加入了 sleep(5); 因為配置寫的是超過1秒就會記錄慢日誌了，5秒是足夠的了)

是否許可權問題

一開始我是懷疑許可權問題,因為我發現建立的日誌許可權是644而且還是root使用者root組。而主程式master是root許可權，子程式worker是app使用者許可權。如下圖

php-fpm-worker

嘗試解決方案1：

把慢日誌檔案許可權改為app使用者許可權並更改讀寫許可權。暴力操作：chmod 777 www123.log.slow 和 chown app:app www123.log.slow。 然後重新訪問測試連線 發現還是沒有日誌寫入。

嘗試解決方案2：

既然更改檔案許可權沒有效果，嘗試把子程式改為root使用者啟動 這樣總不會還有許可權問題了把。 於是乎把上面的配置檔案中的 

user = root
group = root
listen.owner = root
listen.group = root

然後重啟PHP-FPM， 透過 docker logs --tail 100 project 報錯

[16-May-2019 19:04:04] ERROR: [pool www123] please specify user and group other than root
[16-May-2019 19:04:04] ERROR: FPM initialization failed

也就是不能使用root許可權來啟動子程式。到這裡其實陷入了一個死迴圈，老是覺得檔案是master程式建立的 又是root許可權，而worker程式是app使用者許可權不夠，但是又不能使用root許可權啟動子程式，陷入了怪圈。其後還嘗試了更改app使用者的組賦予root許可權等操作都沒有解決問題。

嘗試解決方案3：

這裡也就是上面的 PHP-FPM 的 -R 引數了，來指定使用root許可權啟動子程式，最後雖然php-fpm不報錯了，但是慢日誌檔案還是寫入不了內容。

嘗試解決方案4：

幾經嘗試無果，最後去 Stackoverflow 提了個問題 尋求幫助，最後一位老哥 給了一些提示。他告訴我：你確定真的收到FPM的響應了嗎？

這時我才想起來去看 PHP-FPM的錯誤日誌。在 php-fpm.conf 中增加 error_log = /xx/xx/php-fpm.error.log,然後重啟PHP-FPM，在訪問測試連線請求，發現果然有報錯，錯誤內容如下：

[17-May-2019 10:04:50] NOTICE: fpm is running, pid 12
[17-May-2019 10:04:50] NOTICE: ready to handle connections
[17-May-2019 10:05:04] ERROR: failed to ptrace(ATTACH) child 22: Operation not permitted (1)
[17-May-2019 10:05:04] WARNING: [pool www123] child 22, script '/app/www/public/index.php' (request: "GET /index.php") executing too slow (2.317563 sec), logging

顯示子程式許可權不夠，ptrace 呼叫失敗！

Ptrace是什麼

為了解決這個報錯去找了下 Ptrace 的資料

ptrace 提供了一種機制使得父程式可以觀察和控制子程式的執行過程，ptrace 還可以檢查和修改該子程式的可執行檔案在記憶體中的映象及該子程式所使用的暫存器中的值。這種用法通常來說，主要用於實現對程式插斷點和跟蹤子程式的系統呼叫。

Ptrace是系統級的實現，更多資料可以看下面2個連結 ptrace在linux下是如何工作的 和 trace詳解

為什麼我只是給PHP-FPM開啟慢日誌而已，怎麼又扯到了這個東西？

這個要看PHP-FPM的工作原理了。在FPM進行fork子程式的時候，master程式會做健康檢查，其中有對 request_slowlog_timeout 的判斷。

if (child->slow_logged.tv_sec == 0 && slowlog_timeout &&
     proc.request_stage == FPM_REQUEST_EXECUTING && tv.tv_sec >= slowlog_timeout) {
     str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
     child->slow_logged = proc.accepted;child->tracer = fpm_php_trace;//記錄執行慢的php棧呼叫的回撥函式
     fpm_trace_signal(child->pid);//呼叫ptrace函式，追蹤程式
 ....................
 }
 ................

//開始追蹤程式\
 int fpm_trace_signal(pid_t pid){
    if (0 > ptrace(PTRACE_ATTACH, pid, 0, 0)) {
         zlog(ZLOG_SYSERROR, "failed to ptrace(ATTACH) child %d", pid);
         return -1; 
     }
     return 0;
 }
 //關閉追蹤
int fpm_trace_close(pid_t pid) {
     if (0 > ptrace(PTRACE_DETACH, pid, (void *) 1, 0)) {
         zlog(ZLOG_SYSERROR, "failed to ptrace(DETACH) child %d", pid);
         return -1; 
     } 
    traced_pid = 0;
    return 0;
 } 
 //獲取棧呼叫資訊
 int fpm_trace_get_long(long addr, long *data) { 
     errno = 0;
     *data = ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0);
     if (errno) {
         zlog(ZLOG_SYSERROR, "failed to ptrace(PEEKDATA) pid %d", traced_pid);
         return -1;
    }
    return 0;
}

所以master程式為了監控子程式需要呼叫 ptrace 來實現對子程式監控和追蹤，但是呼叫ptrace卻失敗了。

那會不會是當前的 Docker 容器中並不具備 Ptrace 功能？經過一番查詢還真是這個原因

最終解決

在 Docker官方文件 關於 docker run 命令介紹一欄中有 一個子單元介紹 Runtime privilege and Linux capabilities 就是這裡

docker-privilege

預設情況下，建立的Docker容器具備很多Linux功能，但是也有很多在預設建立時候不提供的功能，其中就包括了 Ptrace 功能，用來跟蹤任意程式的能力。

下面是一個建立容器時候預設不提供的功能列表

docker-not-privilege

解決辦法：

重新建立容器 並新增 --cap-add=SYS_PTRACE 給容器追加Ptrace功能

docker run --name website_name -p 11280:80 --cap-add=SYS_PTRACE -v /data/website/website_name:/app -d showtime/php-javabridge:v1 (PS：不要直接copy,重點在那個cap-add引數上)

然後重新配置PHP-FPM慢日誌配置，在訪問測試連線，終於寫入了慢日誌內容，一天的折騰終於有了結果。

檢視日誌內容如下：

[17-May-2019 10:34:58]  [pool www123] pid 23
script_filename = /home/vagrant/code/admin/public/index.php
[0x00007f95c62120e0] sleep() /home/vagrant/code/admin/public/index.php:20

關於前面的通訊環節我也不是理解的很深入，如果有錯的地方歡迎大家指出或者給出建議，一起學習

參考連結

感謝所有提供幫助的人！

php-fpm doesn't work

how to enable php-fpm slowlog

php slowlog causing ptrace error in docker container

docker run

php-fpm-slow-log

csdn

docker-php-fpm

how-does-ptrace-work

本作品採用《CC 協議》，轉載必須註明作者和本文連結
微信公眾號：碼咚沒 ( ID: codingdongmei )

相關文章