详解php+nginx 服务发生500 502错误排查思路
概述当线上的服务中访问中出现500或者502错误时，需要紧急处理，排查问题，该怎么做？可以通过分析一些错误日志或者跟踪php-fpm进程来进行问题定位。
nginx error_log
nginx的error_log在nginx的配置文件中定义的
server {
listen80;
server_name localhost;
root /var/www;
access_log /Users/jiao/logs/default.access.log;
error_log /Users/jiao/logs/default.error.log;
location / {
index index.html index.htm index.php;
autoindex on;
}
location = /info {
allow 127.0.0.1;
deny all;
rewrite (.*) /.info.php;
}
location ~ \.php$ {
root /var/www;
fastcgi_pass 127.0.0.1:9000;
fastcgi_index index.php;
fastcgi_param SCRIPT_FILENAME /var/www$fastcgi_script_name;
include /usr/local/etc/nginx/fastcgi_params;
}
}
查看error_log
➜tail /Users/jiao/logs/default.error.log
2019/07/17 11:08:18 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文件中配置中定义的
; Error log file
; If it's set to "syslog", log is sent to syslogd instead of being written
; in a local file.
; Note: the default prefix is /usr/local/var
; Default Value: log/php-fpm.log
error_log = log/php-fpm.log
error_log里面的内容是这样的
➜ tail /usr/local/var/log/php-fpm.log
NOTICE: child 81948 started
WARNING: child 77537, script '/var/www/index.php' (request: "GET /index.php") execution timed out (3.801267 sec), terminating
WARNING: child 77537 exited on signal 15 (SIGTERM) after 1503.113967 seconds from start
NOTICE: child 94339 started
可以看到是请求/var/www/index.php文件出现了超时
dtruss
dtruss是动态跟踪命令，可以根据PID，name跟踪进程
mac环境下使用dtruss，linux环境可以使用strace，pstack
➜ dtruss
USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command | -W name }
-p PID # examine this PID
-n name # examine this process name
-t syscall# examine this syscall only
-W name # wait for a process matching this name
-a # print all details
-c # print syscall counts
-d # print relative times (us)
-e # print elapsed times (us)
-f # follow children
-l # force printing pid/lwpid
-o # print on cpu times
-s # print stack backtraces
-L # don't print pid/lwpid
-b bufsize# dynamic variable buf size
eg,
dtruss df -h# run and examine "df -h"
dtruss -p 1871# examine PID 1871
dtruss -n tar# examine all processes called "tar"
dtruss -f test.sh # run test.sh and follow children
跟踪php-fpm：sudo dtruss -a -n php-fpm
此时访问web页面，就可以看到跟踪内容
21416/0x3479b6:1559633 getrusage(0x0, 0x7FFEE1EC0760, 0x0) = 0 0
21416/0x3479b6:156140 getrusage(0xFFFFFFFFFFFFFFFF, 0x7FFEE1EC0760, 0x0) = 0 0
21416/0x3479b6:16277717 poll(0x7FFEE1EC08C0, 0x1, 0x1388) = 1 0
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
21416/0x3479b6:18722924 lstat64("/var/www/index.php\0", 0x7FFEE1ECFF38, 0x0) = 0 0
21416/0x3479b6:188496 lstat64("/var/www\0", 0x7FFEE1ECFDF8, 0x0) = 0 0
21416/0x3479b6:188963 lstat64("/var\0", 0x7FFEE1ECFCB8, 0x0) = 0 0
21416/0x3479b6:1899128 readlink("/var\0", 0x7FFEE1ED0090, 0x400) = 11 0
21416/0x3479b6:190564 lstat64("/private/var\0", 0x7FFEE1ECFB78, 0x0) = 0 0
21416/0x3479b6:191763 lstat64("/private\0", 0x7FFEE1ECFA38, 0x0) = 0 0
21416/0x3479b6:21781814 stat64("/var/www/.user.ini\0", 0x7FFEE1ED0240, 0x0) = -1 Err#2
21416/0x3479b6:221751 setitimer(0x2, 0x7FFEE1ED07E0, 0x0) = 0 0
21416/0x3479b6:222540 sigaction(0x1B, 0x7FFEE1ED0788, 0x7FFEE1ED07B0) = 0 0
21416/0x3479b6:223751 sigprocmask(0x2, 0x7FFEE1ED0804, 0x0) = 0x0 0
21416/0x3479b6:36434840 open_nocancel(".\0", 0x0, 0x1) = 5 0
21416/0x3479b6:364873 fstat64(0x5, 0x7FFEE1ED0110, 0x0) = 0 0
21416/0x3479b6:365372 fcntl_nocancel(0x5, 0x32, 0x10F252158) = 0 0
21416/0x3479b6:3661127 close_nocancel(0x5) = 0 0
21416/0x3479b6:3670107 stat64("/usr/local/var\0", 0x7FFEE1ED0080, 0x0) = 0 0
21416/0x3479b6:3681118 chdir("/var/www\0", 0x0, 0x0) = 0 0
21416/0x3479b6:369840 setitimer(0x2, 0x7FFEE1ED02D0, 0x0) = 0 0
21416/0x3479b6:371063 fcntl(0x3, 0x8, 0x10F3FD858) = 0 0
21416/0x3479b6:373396 stat64("/private/var/www/index.php\0", 0x7FFEE1ECFF10, 0x0) = 0 0
74904/0x332630: 723125 107338119 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770666 107338717 kevent(0x8, 0x0, 0x0) = 0 0
74904/0x332630: 723165 106195420 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770709 106195420 kevent(0x8, 0x0, 0x0) = 0 0
74904/0x332630: 723201 107478616 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770747 107478316 kevent(0x8, 0x0, 0x0) = 0 0
74904/0x332630: 723229 106914113 kevent(0x9, 0x0, 0x0) = 0 0
74902/0x332629: 770777 106914511 kevent(0x8, 0x0, 0x0) = 0 0
21416/0x3479b6:3942 39022337 __semwait_signal(0x703, 0x0, 0x1) = -1 Err#4
74902/0x332629: 77081410325 kill(21416, 15) = 0 0
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 77132572 sigreturn(0x7FFEE1ECFC40, 0x1E, 0xC1A4B78E0404663A) = 0 Err#-2
74902/0x332629: 77133673 kevent(0x8, 0x0, 0x0) = 1 0
dtrace: error on enabled probe ID 2174 (ID 159: syscall::read:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 771352117 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3) = 21416 0
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 773511 1957 1899 fork() = 28060 0
28060/0x3754c5:125:0:0 fork() = 0 0
28060/0x3754c5:12892 bsdthread_register(0x7FFF6774C418, 0x7FFF6774C408, 0x2000) = -1 Err#22
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #13 at DIF offset 68
74902/0x332629: 77373741 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3) = 0 0
74902/0x332629: 77374263 read(0x5, "\0", 0x1) = -1 Err#35
28060/0x3754c5:32040 getpid(0x0, 0x0, 0x0) = 28060 0
28060/0x3754c5:32872 __mac_syscall(0x7FFF67758A17, 0x4, 0x7FFEE1ED0208) = -1 Err#45
28060/0x3754c5:33252 csops(0x6D9C, 0xB, 0x7FFEE1ED0248) = -1 Err#22
28060/0x3754c5:7551411 dup2(0x1, 0x2, 0x0) = 2 0
28060/0x3754c5:7978922 close(0x4) = 0 0
28060/0x3754c5:806116 dup2(0x7, 0x0, 0x0) = 0 0
28060/0x3754c5:81740 geteuid(0x0, 0x0, 0x0) = 501 0
28060/0x3754c5:82030 close(0x5) = 0 0
28060/0x3754c5:82130 close(0x6) = 0 0
28060/0x3754c5:82451 sigaction(0xF, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5:82530 sigaction(0x2, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5:82730 sigaction(0x1E, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5:82830 sigaction(0x1F, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5:82930 sigaction(0x14, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5:83030 sigaction(0x3, 0x7FFEE1ED0688, 0x0) = 0 0
28060/0x3754c5:104330 close(0x7) = 0 0
可以看到系统底层执行的函数，如lstat64获取文件内容信息，kill(21416, 15)kill掉php-fpm进程，fork()出新的php-fpm进程，有兴趣可以深入研究每个指令的作用
以上就是本文的全部内容，希望对大家的学习有所帮助，也希望大家多多支持服务器之家。
原文链接：https://segmentfault.com/a/1190000019788534
文档来源：服务器之家http://www.zzvips.com/article/47227.html
页:
[1]