5

我们的 Web 项目有一个非常奇怪的问题。

我们用:

2 Intel(R) Xeon(R) CPU E5520 @ 2.27GHz
12 GB 内存
我们每秒大约有 20 次点击。每秒 4-5 个请求很重——这是一个搜索请求。
我们使用安装在另一台机器上的 nginx + php-fpm (5.3.22)
MySQL 服务器。
大多数时候,我们的平均负载低于 10,cpu 使用率约为 50%
有时我们的 cpu 使用率约为 95%,之后平均负载增长到 50 甚至更多!
您可以在此处查看平均负载和 CPU 使用率(我在此处发送图像的声誉很低)
负载平均
CPU 使用率

我们必须重新加载 php-fpm ( /etc/init.d/php-fpm reload) 以使情况正常化。
这可以每天发生 4-5 次。
我尝试使用 strace 来检查这种情况。
对不起,长日志!命令 strace -cp PID
PID 的输出是随机的 php-fpm 进程 ID(我们启动 100 个 php-fpm 进程)。
这两个导致高cpu使用率的时刻。

Process 17272 attached - interrupt to quit
Process 17272 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 65.56    0.008817         267        33           munmap
 13.38    0.001799         900         2           clone
  9.66    0.001299           2       589           read
  7.43    0.000999         125         8           mremap
  2.84    0.000382           1       559        96 access
  0.59    0.000080          40         2           waitpid
  0.29    0.000039           0       627           gettimeofday
  0.16    0.000022           0       346           write
  0.04    0.000006           0        56           getcwd
  0.04    0.000005           0       348           poll
  0.00    0.000000           0        55           open
  0.00    0.000000           0        69           close
  0.00    0.000000           0        17           chdir
  0.00    0.000000           0       189           time
  0.00    0.000000           0        28           lseek
  0.00    0.000000           0         2           pipe
  0.00    0.000000           0        17           times
  0.00    0.000000           0         8           brk
  0.00    0.000000           0         8           getrusage
  0.00    0.000000           0        18           setitimer
  0.00    0.000000           0         8           flock
  0.00    0.000000           0         1           nanosleep
  0.00    0.000000           0        11           rt_sigaction
  0.00    0.000000           0        13           rt_sigprocmask
  0.00    0.000000           0         6           pread64
  0.00    0.000000           0         7           pwrite64
  0.00    0.000000           0        33           mmap2
  0.00    0.000000           0        18         4 stat64
  0.00    0.000000           0        34           lstat64
  0.00    0.000000           0        92           fstat64
  0.00    0.000000           0        63           fcntl64
  0.00    0.000000           0        53           clock_gettime
  0.00    0.000000           0         1           socket
  0.00    0.000000           0         1         1 connect
  0.00    0.000000           0         9           accept
  0.00    0.000000           0         1           send
  0.00    0.000000           0        21           recv
  0.00    0.000000           0         9         1 shutdown
  0.00    0.000000           0         1           getsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.013448                  3363       102 total



[root@hp-php ~]# strace -cp 30767
Process 30767 attached - interrupt to quit
Process 30767 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 52.88    0.016926         220        77           munmap
 29.06    0.009301           2      4343           read
  8.73    0.002794         466         6           clone
  3.59    0.001149           0      5598           time
  3.18    0.001017           0      3745           write
  1.12    0.000358           0      7316           gettimeofday
  0.64    0.000205           1       164           fcntl64
  0.39    0.000124          21         6           waitpid
  0.22    0.000070           0      1496       326 access
  0.13    0.000041           0      3769           poll
  0.03    0.000009           0       151           close
  0.02    0.000008           0       114           clock_gettime
  0.02    0.000007           0       110           getcwd
  0.00    0.000000           0       112           open
  0.00    0.000000           0        38           chdir
  0.00    0.000000           0        47           lseek
  0.00    0.000000           0         6           pipe
  0.00    0.000000           0        38           times
  0.00    0.000000           0       135           brk
  0.00    0.000000           0         3           ioctl
  0.00    0.000000           0        14           getrusage
  0.00    0.000000           0        38           setitimer
  0.00    0.000000           0        19           flock
  0.00    0.000000           0        40           mlock
  0.00    0.000000           0        40           munlock
  0.00    0.000000           0         6           nanosleep
  0.00    0.000000           0        27           rt_sigaction
  0.00    0.000000           0        31           rt_sigprocmask
  0.00    0.000000           0        13           pread64
  0.00    0.000000           0        18           pwrite64
  0.00    0.000000           0        78           mmap2
  0.00    0.000000           0       111        10 stat64
  0.00    0.000000           0        49           lstat64
  0.00    0.000000           0       182           fstat64
  0.00    0.000000           0         8           socket
  0.00    0.000000           0         8         5 connect
  0.00    0.000000           0        19           accept
  0.00    0.000000           0         7           send
  0.00    0.000000           0        66           recv
  0.00    0.000000           0         3           recvfrom
  0.00    0.000000           0        20         1 shutdown
  0.00    0.000000           0         5           setsockopt
  0.00    0.000000           0         4           getsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.032009                 28080       342 total

是的,输出脚本会读取很多信息。这个是正常的。
但是为什么 munmap 工作时间很长??!!当我们遇到问题时, munmap总是在顶部!
为了比较,这是在常规情况下跟踪随机 php-fpm 进程的结果:

Process 28606 attached - interrupt to quit
Process 28606 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 45.72    0.001816           1      2601           read
 32.88    0.001306         435         3           clone
  9.19    0.000365           0      2175           write
  6.95    0.000276           0      7521           time
  2.24    0.000089           0      4158           gettimeofday
  2.01    0.000080           1       114           brk
  0.28    0.000011           0      2166           poll
  0.20    0.000008           0       833       155 access
  0.20    0.000008           0        53           recv
  0.18    0.000007           2         3           waitpid
  0.15    0.000006           0        18           munlock
  0.00    0.000000           0        69           open
  0.00    0.000000           0        96           close
  0.00    0.000000           0        29           chdir
  0.00    0.000000           0        36           lseek
  0.00    0.000000           0         3           pipe
  0.00    0.000000           0        29           times
  0.00    0.000000           0        10           getrusage
  0.00    0.000000           0         5           munmap
  0.00    0.000000           0         1           ftruncate
  0.00    0.000000           0        29           setitimer
  0.00    0.000000           0         1           sigreturn
  0.00    0.000000           0        11           flock
  0.00    0.000000           0        18           mlock
  0.00    0.000000           0         5           nanosleep
  0.00    0.000000           0        19           rt_sigaction
  0.00    0.000000           0        24           rt_sigprocmask
  0.00    0.000000           0         6           pread64
  0.00    0.000000           0        12           pwrite64
  0.00    0.000000           0        69           getcwd
  0.00    0.000000           0         5           mmap2
  0.00    0.000000           0        35         7 stat64
  0.00    0.000000           0        41           lstat64
  0.00    0.000000           0        96           fstat64
  0.00    0.000000           0       108           fcntl64
  0.00    0.000000           0        87           clock_gettime
  0.00    0.000000           0         5           socket
  0.00    0.000000           0         4         4 connect
  0.00    0.000000           0        16         2 accept
  0.00    0.000000           0         8           send
  0.00    0.000000           0        15           shutdown
  0.00    0.000000           0         4           getsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.003972                 20541       168 total

Process 29168 attached - interrupt to quit
Process 29168 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 54.81    0.002366           1      1717           read
 26.41    0.001140           1      1696           poll
  8.29    0.000358           0      1662           write
  7.37    0.000318           2       131       121 stat64
  1.53    0.000066           0      3249           gettimeofday
  1.18    0.000051           0       746       525 access
  0.23    0.000010           0        27           fcntl64
  0.19    0.000008           0        62           brk
  0.00    0.000000           0         1           restart_syscall
  0.00    0.000000           0         7           open
  0.00    0.000000           0        16           close
  0.00    0.000000           0         3           chdir
  0.00    0.000000           0      1039           time
  0.00    0.000000           0         1           lseek
  0.00    0.000000           0         3           times
  0.00    0.000000           0         3           ioctl
  0.00    0.000000           0         1           getrusage
  0.00    0.000000           0         4           munmap
  0.00    0.000000           0         3           setitimer
  0.00    0.000000           0         1           sigreturn
  0.00    0.000000           0         1           flock
  0.00    0.000000           0         1           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         2           pwrite64
  0.00    0.000000           0         3           getcwd
  0.00    0.000000           0         4           mmap2
  0.00    0.000000           0         7           fstat64
  0.00    0.000000           0         9           clock_gettime
  0.00    0.000000           0         6           socket
  0.00    0.000000           0         5         1 connect
  0.00    0.000000           0         3         2 accept
  0.00    0.000000           0         5           send
  0.00    0.000000           0        64           recv
  0.00    0.000000           0         3           recvfrom
  0.00    0.000000           0         2           shutdown
  0.00    0.000000           0         1           getsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.004317                 10489       649 total

你可以看到 munmap 不在顶部。
现在我们不知道如何解决这个问题:(
我们检查了下一个潜在问题,答案是“否”:

  • 额外的用户活动
  • 长脚本执行(几秒钟)
  • 使用交换

你能帮助我们吗?

4

0 回答 0