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

2019-10-17 16:39:11王旭

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:  1559  63  3 getrusage(0x0, 0x7FFEE1EC0760, 0x0)   = 0 0
21416/0x3479b6:  1561  4  0 getrusage(0xFFFFFFFFFFFFFFFF, 0x7FFEE1EC0760, 0x0)   = 0 0
21416/0x3479b6:  1627  77  17 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:  1872  29  24 lstat64("/var/www/index.php", 0x7FFEE1ECFF38, 0x0)   = 0 0
21416/0x3479b6:  1884  9  6 lstat64("/var/www", 0x7FFEE1ECFDF8, 0x0)   = 0 0
21416/0x3479b6:  1889  6  3 lstat64("/var", 0x7FFEE1ECFCB8, 0x0)   = 0 0
21416/0x3479b6:  1899  12  8 readlink("/var", 0x7FFEE1ED0090, 0x400)   = 11 0
21416/0x3479b6:  1905  6  4 lstat64("/private/var", 0x7FFEE1ECFB78, 0x0)   = 0 0
21416/0x3479b6:  1917  6  3 lstat64("/private", 0x7FFEE1ECFA38, 0x0)   = 0 0
21416/0x3479b6:  2178  18  14 stat64("/var/www/.user.ini", 0x7FFEE1ED0240, 0x0)   = -1 Err#2
21416/0x3479b6:  2217  5  1 setitimer(0x2, 0x7FFEE1ED07E0, 0x0)   = 0 0
21416/0x3479b6:  2225  4  0 sigaction(0x1B, 0x7FFEE1ED0788, 0x7FFEE1ED07B0)   = 0 0
21416/0x3479b6:  2237  5  1 sigprocmask(0x2, 0x7FFEE1ED0804, 0x0)   = 0x0 0
21416/0x3479b6:  3643  48  40 open_nocancel(".", 0x0, 0x1)   = 5 0
21416/0x3479b6:  3648  7  3 fstat64(0x5, 0x7FFEE1ED0110, 0x0)   = 0 0
21416/0x3479b6:  3653  7  2 fcntl_nocancel(0x5, 0x32, 0x10F252158)   = 0 0
21416/0x3479b6:  3661  12  7 close_nocancel(0x5)   = 0 0
21416/0x3479b6:  3670  10  7 stat64("/usr/local/var", 0x7FFEE1ED0080, 0x0)   = 0 0
21416/0x3479b6:  3681  11  8 chdir("/var/www", 0x0, 0x0)   = 0 0
21416/0x3479b6:  3698  4  0 setitimer(0x2, 0x7FFEE1ED02D0, 0x0)   = 0 0
21416/0x3479b6:  3710  6  3 fcntl(0x3, 0x8, 0x10F3FD858)   = 0 0
21416/0x3479b6:  3733  9  6 stat64("/private/var/www/index.php", 0x7FFEE1ECFF10, 0x0)   = 0 0
74904/0x332630: 723125 1073381  19 kevent(0x9, 0x0, 0x0)   = 0 0
74902/0x332629: 770666 1073387  17 kevent(0x8, 0x0, 0x0)   = 0 0
74904/0x332630: 723165 1061954  20 kevent(0x9, 0x0, 0x0)   = 0 0
74902/0x332629: 770709 1061954  20 kevent(0x8, 0x0, 0x0)   = 0 0
74904/0x332630: 723201 1074786  16 kevent(0x9, 0x0, 0x0)   = 0 0
74902/0x332629: 770747 1074783  16 kevent(0x8, 0x0, 0x0)   = 0 0
74904/0x332630: 723229 1069141  13 kevent(0x9, 0x0, 0x0)   = 0 0
74902/0x332629: 770777 1069145  11 kevent(0x8, 0x0, 0x0)   = 0 0
21416/0x3479b6:  3942 3902233  7 __semwait_signal(0x703, 0x0, 0x1)   = -1 Err#4
74902/0x332629: 770814  103  25 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: 771325  7  2 sigreturn(0x7FFEE1ECFC40, 0x1E, 0xC1A4B78E0404663A)   = 0 Err#-2
74902/0x332629: 771336  7  3 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: 771352  11  7 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:  128  9  2 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: 773737  4  1 wait4(0xFFFFFFFFFFFFFFFF, 0x7FFEE1ED0748, 0x3)   = 0 0
74902/0x332629: 773742  6  3 read(0x5, "", 0x1)   = -1 Err#35
28060/0x3754c5:  320  4  0 getpid(0x0, 0x0, 0x0)   = 28060 0
28060/0x3754c5:  328  7  2 __mac_syscall(0x7FFF67758A17, 0x4, 0x7FFEE1ED0208)   = -1 Err#45
28060/0x3754c5:  332  5  2 csops(0x6D9C, 0xB, 0x7FFEE1ED0248)   = -1 Err#22
28060/0x3754c5:  755  14  11 dup2(0x1, 0x2, 0x0)   = 2 0
28060/0x3754c5:  797  89  22 close(0x4)   = 0 0
28060/0x3754c5:  806  11  6 dup2(0x7, 0x0, 0x0)   = 0 0
28060/0x3754c5:  817  4  0 geteuid(0x0, 0x0, 0x0)   = 501 0
28060/0x3754c5:  820  3  0 close(0x5)   = 0 0
28060/0x3754c5:  821  3  0 close(0x6)   = 0 0
28060/0x3754c5:  824  5  1 sigaction(0xF, 0x7FFEE1ED0688, 0x0)   = 0 0
28060/0x3754c5:  825  3  0 sigaction(0x2, 0x7FFEE1ED0688, 0x0)   = 0 0
28060/0x3754c5:  827  3  0 sigaction(0x1E, 0x7FFEE1ED0688, 0x0)   = 0 0
28060/0x3754c5:  828  3  0 sigaction(0x1F, 0x7FFEE1ED0688, 0x0)   = 0 0
28060/0x3754c5:  829  3  0 sigaction(0x14, 0x7FFEE1ED0688, 0x0)   = 0 0
28060/0x3754c5:  830  3  0 sigaction(0x3, 0x7FFEE1ED0688, 0x0)   = 0 0
28060/0x3754c5:  1043  3  0 close(0x7)   = 0 0