小知识:详解php+nginx 服务发生500 502错误排查思路

概述

当线上的服务中访问中出现500或者502错误时,需要紧急处理,排查问题,该怎么做?可以通过分析一些错误日志或者跟踪php-fpm进程来进行问题定位。

nginx error_log

nginx的error_log在nginx的配置文件中定义的

01server {
02listen  80;
03server_name localhost;
04root   /var/www;
05
06access_log /Users/jiao/logs/default.access.log;
07error_log /Users/jiao/logs/default.error.log;
08location / {
09index index.html index.htm index.php;
10autoindex on;
11}
12location = /info {
13allow 127.0.0.1;
14deny all;
15rewrite (.*) /.info.php;
16}
17location ~ \.php$ {
18root /var/www;
19fastcgi_pass 127.0.0.1:9000;
20fastcgi_index index.php;
21fastcgi_param SCRIPT_FILENAME /var/www$fastcgi_script_name;
22include /usr/local/etc/nginx/fastcgi_params;
23}
24}

查看error_log

➜  tail /Users/jiao/logs/default.error.log

2019/07/17 11:08:18 [error] 77416#0: *76 kevent() reported about an closed connection (54: Connection reset by peer) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: “GET / HTTP/1.1”, upstream: “fastcgi://127.0.0.1:9000”, host: “localhost”

发现出现了Connection reset by peer,连接被重置了,此时可以再查看php-fpm的error_log进一步分析问题

php-fpm error_log

php-fpm的error_log在php-fpm.conf文件中配置中定义的

1; Error log file
2; If its set to “syslog”, log is sent to syslogd instead of being written
3; in a local file.
4; Note: the default prefix is /usr/local/var
5; Default Value: log/php-fpm.log
6error_log = log/php-fpm.log

error_log里面的内容是这样的

1➜ tail /usr/local/var/log/php-fpm.log
2[17-Jul-2019 10:49:54] NOTICE: [pool www] child 81948 started
3[17-Jul-2019 11:08:18] WARNING: [pool www] child 77537, script /var/www/index.php (request: “GET /index.php”) execution timed out (3.801267 sec), terminating
4[17-Jul-2019 11:08:18] WARNING: [pool www] child 77537 exited on signal 15 (SIGTERM) after 1503.113967 seconds from start
5[17-Jul-2019 11:08:18] NOTICE: [pool www] child 94339 started

可以看到是请求/var/www/index.php文件出现了超时

dtruss

dtruss是动态跟踪命令,可以根据PID,name跟踪进程

mac环境下使用dtruss,linux环境可以使用strace,pstack

1➜ dtruss
2USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command | -W name }
01-p PID   # examine this PID
02-n name   # examine this process name
03-t syscall  # examine this syscall only
04-W name   # wait for a process matching this name
05-a    # print all details
06-c    # print syscall counts
07-d    # print relative times (us)
08-e    # print elapsed times (us)
09-f    # follow children
10-l    # force printing pid/lwpid
11-o    # print on cpu times
12-s    # print stack backtraces
13-L    # dont print pid/lwpid
14-b bufsize  # dynamic variable buf size

eg,

1dtruss df -h  # run and examine “df -h”
2dtruss -p 1871  # examine PID 1871
3dtruss -n tar  # examine all processes called “tar”
4dtruss -f test.sh # run test.sh and follow children

跟踪php-fpm:sudo dtruss -a -n php-fpm 

此时访问web页面,就可以看到跟踪内容

0121416/0x3479b6:  1559  63  3 getrusage(0x0, 0x7FFEE1EC0760, 0x0)   = 0 0
0221416/0x3479b6:  1561  4  0 getrusage(0xFFFFFFFFFFFFFFFF, 0x7FFEE1EC0760, 0x0)   = 0 0
0321416/0x3479b6:  1627  77  17 poll(0x7FFEE1EC08C0, 0x1, 0x1388)   = 1 0
04dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
05dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
06dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
07dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
08dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
0921416/0x3479b6:  1872  29  24 lstat64(“/var/www/index.php\0”, 0x7FFEE1ECFF38, 0x0)   = 0 0
1021416/0x3479b6:  1884  9  6 lstat64(“/var/www\0”, 0x7FFEE1ECFDF8, 0x0)   = 0 0
1121416/0x3479b6:  1889  6  3 lstat64(“/var\0”, 0x7FFEE1ECFCB8, 0x0)   = 0 0
1221416/0x3479b6:  1899  12  8 readlink(“/var\0”, 0x7FFEE1ED0090, 0x400)   = 11 0
1321416/0x3479b6:  1905  6  4 lstat64(“/private/var\0”, 0x7FFEE1ECFB78, 0x0)   = 0 0
1421416/0x3479b6:  1917  6  3 lstat64(“/private\0”, 0x7FFEE1ECFA38, 0x0)   = 0 0
1521416/0x3479b6:  2178  18  14 stat64(“/var/www/.user.ini\0”, 0x7FFEE1ED0240, 0x0)   = -1 Err#2
1621416/0x3479b6:  2217  5  1 setitimer(0x2, 0x7FFEE1ED07E0, 0x0)   = 0 0
1721416/0x3479b6:  2225  4  0 sigaction(0x1B, 0x7FFEE1ED0788, 0x7FFEE1ED07B0)   = 0 0
1821416/0x3479b6:  2237  5  1 sigprocmask(0x2, 0x7FFEE1ED0804, 0x0)   = 0x0 0
1921416/0x3479b6:  3643  48  40 open_nocancel(“.\0”, 0x0, 0x1)   = 5 0
2021416/0x3479b6:  3648  7  3 fstat64(0x5, 0x7FFEE1ED0110, 0x0)   = 0 0
2121416/0x3479b6:  3653  7  2 fcntl_nocancel(0x5, 0x32, 0x10F252158)   = 0 0
2221416/0x3479b6:  3661  12  7 close_nocancel(0x5)   = 0 0
2321416/0x3479b6:  3670  10  7 stat64(“/usr/local/var\0”, 0x7FFEE1ED0080, 0x0)   = 0 0
2421416/0x3479b6:  3681  11  8 chdir(“/var/www\0”, 0x0, 0x0)   = 0 0
2521416/0x3479b6:  3698  4  0 setitimer(0x2, 0x7FFEE1ED02D0, 0x0)   = 0 0
2621416/0x3479b6:  3710  6  3 fcntl(0x3, 0x8, 0x10F3FD858)   = 0 0
2721416/0x3479b6:  3733  9  6 stat64(“/private/var/www/index.php\0”, 0x7FFEE1ECFF10, 0x0)   = 0 0
2874904/0x332630: 723125 1073381  19 kevent(0x9, 0x0, 0x0)   = 0 0
2974902/0x332629: 770666 1073387  17 kevent(0x8, 0x0, 0x0)   = 0 0
3074904/0x332630: 723165 1061954  20 kevent(0x9, 0x0, 0x0)   = 0 0
3174902/0x332629: 770709 1061954  20 kevent(0x8, 0x0, 0x0)   = 0 0
3274904/0x332630: 723201 1074786  16 kevent(0x9, 0x0, 0x0)   = 0 0
3374902/0x332629: 770747 1074783  16 kevent(0x8, 0x0, 0x0)   = 0 0
3474904/0x332630: 723229 1069141  13 kevent(0x9, 0x0, 0x0)   = 0 0
3574902/0x332629: 770777 1069145  11 kevent(0x8, 0x0, 0x0)   = 0 0
3621416/0x3479b6:  3942 3902233  7 __semwait_signal(0x703, 0x0, 0x1)   = -1 Err#4
3774902/0x332629: 770814  103  25 kill(21416, 15)   = 0 0
38dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
39dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
4074902/0x332629: 771325  7  2 sigreturn(0x7FFEE1ECFC40, 0x1E, 0xC1A4B78E0404663A)   = 0 Err#-2
4174902/0x332629: 771336  7  3 kevent(0x8, 0x0, 0x0)   = 1 0
42dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
4374902/0x332629: 771352  11  7 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3)   = 21416 0
44dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
4574902/0x332629: 773511 1957 1899 fork()   = 28060 0
4628060/0x3754c5:  125:  0:  0 fork()   = 0 0
4728060/0x3754c5:  128  9  2 bsdthread_register(0x7FFF6774C418, 0x7FFF6774C408, 0x2000)   = -1 Err#22
48dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
4974902/0x332629: 773737  4  1 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3)   = 0 0
5074902/0x332629: 773742  6  3 read(0x5, “\0”, 0x1)   = -1 Err#35
5128060/0x3754c5:  320  4  0 getpid(0x0, 0x0, 0x0)   = 28060 0
5228060/0x3754c5:  328  7  2 __mac_syscall(0x7FFF67758A17, 0x4, 0x7FFEE1ED0208)   = -1 Err#45
5328060/0x3754c5:  332  5  2 csops(0x6D9C, 0xB, 0x7FFEE1ED0248)   = -1 Err#22
5428060/0x3754c5:  755  14  11 dup2(0x1, 0x2, 0x0)   = 2 0
5528060/0x3754c5:  797  89  22 close(0x4)   = 0 0
5628060/0x3754c5:  806  11  6 dup2(0x7, 0x0, 0x0)   = 0 0
5728060/0x3754c5:  817  4  0 geteuid(0x0, 0x0, 0x0)   = 501 0
5828060/0x3754c5:  820  3  0 close(0x5)   = 0 0
5928060/0x3754c5:  821  3  0 close(0x6)   = 0 0
6028060/0x3754c5:  824  5  1 sigaction(0xF, 0x7FFEE1ED0688, 0x0)   = 0 0
6128060/0x3754c5:  825  3  0 sigaction(0x2, 0x7FFEE1ED0688, 0x0)   = 0 0
6228060/0x3754c5:  827  3  0 sigaction(0x1E, 0x7FFEE1ED0688, 0x0)   = 0 0
6328060/0x3754c5:  828  3  0 sigaction(0x1F, 0x7FFEE1ED0688, 0x0)   = 0 0
6428060/0x3754c5:  829  3  0 sigaction(0x14, 0x7FFEE1ED0688, 0x0)   = 0 0
6528060/0x3754c5:  830  3  0 sigaction(0x3, 0x7FFEE1ED0688, 0x0)   = 0 0
6628060/0x3754c5:  1043  3  0 close(0x7)   = 0 0

可以看到系统底层执行的函数,如lstat64获取文件内容信息,kill(21416, 15)kill掉php-fpm进程,fork()出新的php-fpm进程,有兴趣可以深入研究每个指令的作用

以上就是本文的全部内容,希望对大家的学习有所帮助,也希望大家多多支持服务器之家。

声明: 猿站网有关资源均来自网络搜集与网友提供,任何涉及商业盈利目的的均不得使用,否则产生的一切后果将由您自己承担! 本平台资源仅供个人学习交流、测试使用 所有内容请在下载后24小时内删除,制止非法恶意传播,不对任何下载或转载者造成的危害负任何法律责任!也请大家支持、购置正版! 。本站一律禁止以任何方式发布或转载任何违法的相关信息访客发现请向站长举报,会员发帖仅代表会员个人观点,并不代表本站赞同其观点和对其真实性负责。本网站的资源部分来源于网络,如有侵权烦请发送邮件至:2697268773@qq.com进行处理。
建站知识

小知识:学习Linux的七点忠告 推荐

2023-5-19 2:56:14

建站知识

小知识:在 linux 的命令行输出进度条

2023-5-19 3:04:26

0 条回复 A文章作者 M管理员
    暂无讨论,说说你的看法吧
个人中心
购物车
优惠劵
今日签到
有新私信 私信列表
搜索