详解php+nginx 服务发生500 502错误排查思路
概述
当线上的服务中访问中出现500或者502错误时，需要紧急处理，排查问题，该怎么做？可以通过分析一些错误日志或者跟踪php-fpm进程来进行问题定位。
nginxerror_log
nginx的error_log在nginx的配置文件中定义的
server{
listen80;
server_namelocalhost;
root/var/www;
access_log/Users/jiao/logs/default.access.log;
error_log/Users/jiao/logs/default.error.log;
location/{
indexindex.htmlindex.htmindex.php;
autoindexon;
}
location=/info{
allow127.0.0.1;
denyall;
rewrite(.*)/.info.php;
}
location~\.php${
root/var/www;
fastcgi_pass127.0.0.1:9000;
fastcgi_indexindex.php;
fastcgi_paramSCRIPT_FILENAME/var/www$fastcgi_script_name;
include/usr/local/etc/nginx/fastcgi_params;
}
}
查看error_log
➜ tail/Users/jiao/logs/default.error.log
2019/07/1711:08:18[error]77416#0:*76kevent()reportedaboutanclosedconnection(54:Connectionresetbypeer)whilereadingresponseheaderfromupstream,client:127.0.0.1,server:localhost,request:"GET/HTTP/1.1",upstream:"fastcgi://127.0.0.1:9000",host:"localhost"
发现出现了Connectionresetbypeer，连接被重置了，此时可以再查看php-fpm的error_log进一步分析问题
php-fpmerror_log
php-fpm的error_log在php-fpm.conf文件中配置中定义的
;Errorlogfile ;Ifit'ssetto"syslog",logissenttosyslogdinsteadofbeingwritten ;inalocalfile. ;Note:thedefaultprefixis/usr/local/var ;DefaultValue:log/php-fpm.log error_log=log/php-fpm.log
error_log里面的内容是这样的
➜tail/usr/local/var/log/php-fpm.log [17-Jul-201910:49:54]NOTICE:[poolwww]child81948started [17-Jul-201911:08:18]WARNING:[poolwww]child77537,script'/var/www/index.php'(request:"GET/index.php")executiontimedout(3.801267sec),terminating [17-Jul-201911:08:18]WARNING:[poolwww]child77537exitedonsignal15(SIGTERM)after1503.113967secondsfromstart [17-Jul-201911:08:18]NOTICE:[poolwww]child94339started
可以看到是请求/var/www/index.php文件出现了超时
dtruss
dtruss是动态跟踪命令，可以根据PID，name跟踪进程
mac环境下使用dtruss，linux环境可以使用strace，pstack
➜dtruss
USAGE:dtruss[-acdefholLs][-tsyscall]{-pPID|-nname|command|-Wname}
-pPID#examinethisPID -nname#examinethisprocessname -tsyscall#examinethissyscallonly -Wname#waitforaprocessmatchingthisname -a#printalldetails -c#printsyscallcounts -d#printrelativetimes(us) -e#printelapsedtimes(us) -f#followchildren -l#forceprintingpid/lwpid -o#printoncputimes -s#printstackbacktraces -L#don'tprintpid/lwpid -bbufsize#dynamicvariablebufsize
eg,
dtrussdf-h#runandexamine"df-h" dtruss-p1871#examinePID1871 dtruss-ntar#examineallprocessescalled"tar" dtruss-ftest.sh#runtest.shandfollowchildren
跟踪php-fpm：sudodtruss-a-nphp-fpm
此时访问web页面，就可以看到跟踪内容
21416/0x3479b6:1559633getrusage(0x0,0x7FFEE1EC0760,0x0)=00
21416/0x3479b6:156140getrusage(0xFFFFFFFFFFFFFFFF,0x7FFEE1EC0760,0x0)=00
21416/0x3479b6:16277717poll(0x7FFEE1EC08C0,0x1,0x1388)=10
dtrace:erroronenabledprobeID2174(ID159:syscall::read:return):invalidkernelaccessinaction#13atDIFoffset68
dtrace:erroronenabledprobeID2174(ID159:syscall::read:return):invalidkernelaccessinaction#13atDIFoffset68
dtrace:erroronenabledprobeID2174(ID159:syscall::read:return):invalidkernelaccessinaction#13atDIFoffset68
dtrace:erroronenabledprobeID2174(ID159:syscall::read:return):invalidkernelaccessinaction#13atDIFoffset68
dtrace:erroronenabledprobeID2174(ID159:syscall::read:return):invalidkernelaccessinaction#13atDIFoffset68
21416/0x3479b6:18722924lstat64("/var/www/index.php\0",0x7FFEE1ECFF38,0x0)=00
21416/0x3479b6:188496lstat64("/var/www\0",0x7FFEE1ECFDF8,0x0)=00
21416/0x3479b6:188963lstat64("/var\0",0x7FFEE1ECFCB8,0x0)=00
21416/0x3479b6:1899128readlink("/var\0",0x7FFEE1ED0090,0x400)=110
21416/0x3479b6:190564lstat64("/private/var\0",0x7FFEE1ECFB78,0x0)=00
21416/0x3479b6:191763lstat64("/private\0",0x7FFEE1ECFA38,0x0)=00
21416/0x3479b6:21781814stat64("/var/www/.user.ini\0",0x7FFEE1ED0240,0x0)=-1Err#2
21416/0x3479b6:221751setitimer(0x2,0x7FFEE1ED07E0,0x0)=00
21416/0x3479b6:222540sigaction(0x1B,0x7FFEE1ED0788,0x7FFEE1ED07B0)=00
21416/0x3479b6:223751sigprocmask(0x2,0x7FFEE1ED0804,0x0)=0x00
21416/0x3479b6:36434840open_nocancel(".\0",0x0,0x1)=50
21416/0x3479b6:364873fstat64(0x5,0x7FFEE1ED0110,0x0)=00
21416/0x3479b6:365372fcntl_nocancel(0x5,0x32,0x10F252158)=00
21416/0x3479b6:3661127close_nocancel(0x5)=00
21416/0x3479b6:3670107stat64("/usr/local/var\0",0x7FFEE1ED0080,0x0)=00
21416/0x3479b6:3681118chdir("/var/www\0",0x0,0x0)=00
21416/0x3479b6:369840setitimer(0x2,0x7FFEE1ED02D0,0x0)=00
21416/0x3479b6:371063fcntl(0x3,0x8,0x10F3FD858)=00
21416/0x3479b6:373396stat64("/private/var/www/index.php\0",0x7FFEE1ECFF10,0x0)=00
74904/0x332630:723125107338119kevent(0x9,0x0,0x0)=00
74902/0x332629:770666107338717kevent(0x8,0x0,0x0)=00
74904/0x332630:723165106195420kevent(0x9,0x0,0x0)=00
74902/0x332629:770709106195420kevent(0x8,0x0,0x0)=00
74904/0x332630:723201107478616kevent(0x9,0x0,0x0)=00
74902/0x332629:770747107478316kevent(0x8,0x0,0x0)=00
74904/0x332630:723229106914113kevent(0x9,0x0,0x0)=00
74902/0x332629:770777106914511kevent(0x8,0x0,0x0)=00
21416/0x3479b6:394239022337__semwait_signal(0x703,0x0,0x1)=-1Err#4
74902/0x332629:77081410325kill(21416,15)=00
dtrace:erroronenabledprobeID2172(ID161:syscall::write:return):invalidkernelaccessinaction#13atDIFoffset68
dtrace:erroronenabledprobeID2172(ID161:syscall::write:return):invalidkernelaccessinaction#13atDIFoffset68
74902/0x332629:77132572sigreturn(0x7FFEE1ECFC40,0x1E,0xC1A4B78E0404663A)=0Err#-2
74902/0x332629:77133673kevent(0x8,0x0,0x0)=10
dtrace:erroronenabledprobeID2174(ID159:syscall::read:return):invalidkernelaccessinaction#13atDIFoffset68
74902/0x332629:771352117wait4(0xFFFFFFFFFFFFFFFF,0x7FFEE1ED0748,0x3)=214160
dtrace:erroronenabledprobeID2172(ID161:syscall::write:return):invalidkernelaccessinaction#13atDIFoffset68
74902/0x332629:77351119571899fork()=280600
28060/0x3754c5:125:0:0fork()=00
28060/0x3754c5:12892bsdthread_register(0x7FFF6774C418,0x7FFF6774C408,0x2000)=-1Err#22
dtrace:erroronenabledprobeID2172(ID161:syscall::write:return):invalidkernelaccessinaction#13atDIFoffset68
74902/0x332629:77373741wait4(0xFFFFFFFFFFFFFFFF,0x7FFEE1ED0748,0x3)=00
74902/0x332629:77374263read(0x5,"\0",0x1)=-1Err#35
28060/0x3754c5:32040getpid(0x0,0x0,0x0)=280600
28060/0x3754c5:32872__mac_syscall(0x7FFF67758A17,0x4,0x7FFEE1ED0208)=-1Err#45
28060/0x3754c5:33252csops(0x6D9C,0xB,0x7FFEE1ED0248)=-1Err#22
28060/0x3754c5:7551411dup2(0x1,0x2,0x0)=20
28060/0x3754c5:7978922close(0x4)=00
28060/0x3754c5:806116dup2(0x7,0x0,0x0)=00
28060/0x3754c5:81740geteuid(0x0,0x0,0x0)=5010
28060/0x3754c5:82030close(0x5)=00
28060/0x3754c5:82130close(0x6)=00
28060/0x3754c5:82451sigaction(0xF,0x7FFEE1ED0688,0x0)=00
28060/0x3754c5:82530sigaction(0x2,0x7FFEE1ED0688,0x0)=00
28060/0x3754c5:82730sigaction(0x1E,0x7FFEE1ED0688,0x0)=00
28060/0x3754c5:82830sigaction(0x1F,0x7FFEE1ED0688,0x0)=00
28060/0x3754c5:82930sigaction(0x14,0x7FFEE1ED0688,0x0)=00
28060/0x3754c5:83030sigaction(0x3,0x7FFEE1ED0688,0x0)=00
28060/0x3754c5:104330close(0x7)=00
可以看到系统底层执行的函数，如lstat64获取文件内容信息，kill(21416,15)kill掉php-fpm进程，fork()出新的php-fpm进程，有兴趣可以深入研究每个指令的作用
参考
https://www.nhooo.com/article/165773.htm
以上就是本文的全部内容，希望对大家的学习有所帮助，也希望大家多多支持毛票票。