PHP-FPM可以创建慢日志文件，但是却不能给慢日志文件写入内容

发表于   |   分类于   |  

说来惭愧，公司的服务器环境用了那么久连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的安装目录下，我的内容如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
/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 中配置如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
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

1
2
3
4
/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配置慢日志的说明网上一大堆。反正搜什么都是给你显示怎么配置的搜索结果，真是够了！

常规配置如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
; 这里是你的子进程的名字 这里我写的是 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秒是足够的了)

是否权限问题

一开始我是怀疑权限问题,因为我发现创建的日志权限是600而且还是root用户root组。而主进程master是root权限，子进程worker是app用户权限。如下图

php-fpm-worker

尝试解决方案1：

把慢日志文件权限改为app用户权限并更改读写权限。暴力操作：chmod 777 www123.log.slow 和 chown app:app www123.log.slow。 然后重新访问测试连接 发现还是没有日志写入。

尝试解决方案2：

既然更改文件权限没有效果，尝试把子进程改为root用户启动 这样总不会还有权限问题了把。 于是乎把上面的配置文件中的 

1
2
3
4
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，在访问测试连接请求，发现果然有报错，错误内容如下：

1
2
3
4
[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 的判断。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
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慢日志配置，在访问测试连接，终于写入了慢日志内容，一天的折腾终于有了结果。

查看日志内容如下：

1
2
3
[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

-------------The End-------------