I have already described how to strace PHP-FPM processes, but you can also display a strace summary to get detailed information about count time, calls, and errors for each syscall.
Prerequisites
Install strace utility.
$ sudo apt install strace
$ strace -V strace -- version 5.5 Copyright (c) 1991-2020 The strace developers <https://strace.io>. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. Optional features enabled: stack-trace=libunwind stack-demangle m32-mpers mx32-mpers
Execute strace to display count time, calls, and errors for each syscall for PHP-FPM process activity.
$ sudo strace --summary-only -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
strace: Process 1829 attached strace: Process 2602 attached strace: Process 2603 attached strace: Process 2604 attached strace: Process 2605 attached strace: Process 2606 attached strace: Process 3842 attached strace: Process 28660 attached strace: Process 20049 attached strace: Process 1829 detached strace: Process 2602 detached strace: Process 2603 detached strace: Process 2604 detached strace: Process 2605 detached strace: Process 2606 detached strace: Process 3842 detached strace: Process 28660 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 25.78 0.038760 4 8206 5169 access 22.49 0.033811 5 5699 22 lstat 9.55 0.014364 3 4273 poll 9.40 0.014136 3 3551 recvfrom 8.33 0.012523 4 2863 7 stat 5.75 0.008647 9 912 sendto 3.62 0.005437 2 1874 fstat 3.13 0.004701 3 1344 fcntl 2.94 0.004422 6 718 munmap 2.54 0.003812 5 717 mmap 2.10 0.003155 4 634 1 open 1.73 0.002599 3 704 close 0.96 0.001448 30 47 47 connect 0.32 0.000481 3 158 read 0.20 0.000307 3 93 setsockopt 0.17 0.000259 3 71 readlink 0.17 0.000255 5 48 socket 0.16 0.000236 6 35 write 0.14 0.000204 3 63 getsockopt 0.12 0.000186 11 16 epoll_wait 0.07 0.000111 2 53 lseek 0.06 0.000094 1 56 rt_sigaction 0.05 0.000080 2 36 getcwd 0.03 0.000050 1 28 setitimer 0.03 0.000050 7 7 accept 0.03 0.000049 2 19 umask 0.03 0.000044 3 14 dup 0.01 0.000020 5 4 getdents 0.01 0.000020 1 14 times 0.01 0.000018 1 14 chdir 0.01 0.000017 2 7 shutdown 0.01 0.000013 3 4 brk 0.01 0.000012 12 1 sendmsg 0.01 0.000010 1 7 rt_sigprocmask 0.01 0.000010 5 2 openat 0.01 0.000009 9 1 clone 0.00 0.000002 2 1 getuid 0.00 0.000002 2 1 getgid 0.00 0.000002 2 1 geteuid 0.00 0.000002 2 1 getegid 0.00 0.000001 1 1 set_robust_list 0.00 0.000000 0 1 madvise 0.00 0.000000 0 1 getsockname 0.00 0.000000 0 1 getpeername ------ ----------- ----------- --------- --------- ---------------- 100.00 0.150359 4 32301 5246 total
Execute strace to track PHP-FPM process activity and display count time, calls, and errors for each syscall at the end.
$ sudo strace --summary -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t/ /g')
strace: Process 1829 attached strace: Process 2602 attached strace: Process 2603 attached strace: Process 2604 attached strace: Process 2605 attached strace: Process 2606 attached strace: Process 3842 attached strace: Process 28660 attached [...] [pid 1829] socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 9 [pid 1829] getsockopt(9, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0 [pid 1829] setsockopt(9, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0 [pid 1829] getuid() = 0 [pid 1829] geteuid() = 0 [pid 1829] getgid() = 0 [pid 1829] getegid() = 0 [...] strace: Process 2602 detached strace: Process 2603 detached strace: Process 2604 detached strace: Process 2605 detached strace: Process 2606 detached strace: Process 3842 detached strace: Process 28660 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 62.10 0.000136 10 13 epoll_wait 24.66 0.000054 4 13 getsockopt 5.48 0.000012 12 1 sendmsg 2.74 0.000006 6 1 socket 1.83 0.000004 4 1 close 0.91 0.000002 2 1 setsockopt 0.91 0.000002 2 1 getegid 0.46 0.000001 1 1 getuid 0.46 0.000001 1 1 getgid 0.46 0.000001 1 1 geteuid ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000219 6 34 total
Execute strace to display count time, calls, and errors for each syscall for PHP-FPM process activity sorted by error count.
$ strace --summary-only --summary-sort-by=errors -f $(pgrep php-fpm | paste -s | sed -e 's/\([0-9]\+\)/-p \1/g' -e 's/\t / /g')
strace: Process 1829 attached strace: Process 2602 attached strace: Process 2603 attached strace: Process 2604 attached strace: Process 2605 attached strace: Process 2606 attached strace: Process 3842 attached strace: Process 28660 attached strace: Process 1829 detached strace: Process 2602 detached strace: Process 2603 detached strace: Process 2604 detached strace: Process 2605 detached strace: Process 2606 detached strace: Process 3842 detached strace: Process 28660 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 44.97 0.012896 4 2653 1708 access 0.99 0.000283 20 14 14 connect 13.19 0.003781 5 732 7 stat 1.47 0.000422 3 125 read 1.35 0.000387 11 35 write 0.78 0.000224 5 42 open 0.92 0.000265 3 79 close 0.74 0.000212 2 77 fstat 24.65 0.007068 5 1283 lstat 2.20 0.000630 3 210 poll 0.65 0.000186 2 70 lseek 0.11 0.000032 4 7 mmap 0.30 0.000087 5 15 munmap 0.60 0.000173 3 56 rt_sigaction 0.08 0.000024 3 7 rt_sigprocmask 0.15 0.000043 3 14 dup 0.24 0.000070 2 28 setitimer 0.24 0.000069 4 16 socket 0.35 0.000101 14 7 accept 0.89 0.000256 9 28 sendto 2.42 0.000694 4 163 recvfrom 0.09 0.000025 12 2 sendmsg 0.05 0.000013 1 7 shutdown 0.10 0.000028 1 16 setsockopt 0.31 0.000090 3 30 getsockopt 0.41 0.000117 2 56 fcntl 0.36 0.000104 4 21 getcwd 0.22 0.000064 4 14 chdir 0.16 0.000046 3 13 readlink 0.20 0.000058 2 21 umask 0.13 0.000037 2 14 times 0.01 0.000003 1 2 getuid 0.01 0.000003 1 2 getgid 0.01 0.000003 1 2 geteuid 0.01 0.000003 1 2 getegid 0.62 0.000178 11 16 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.028675 4 5879 1729 total