记一次 PHP-FPM 可以创建慢日志，但是却不能写入内容的折腾过程

reggie 的个人博客 / 4 / 4 / 创建于 5年前

说来惭愧，公司的服务器环境用了那么久连 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