Categories
SysOps

How to display strace summary

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