NginxとPHP-FPMの処理遅い、レスポンスできない問題分析

現象：Webサーバーはリクエストへの応答ができない、遅い
時間：2019年2月6日 10:30分から〜10:45分の間

AWSのワーニングとログ情報
■admin-alert APP [10:41 AM]
@channel [https://xxx-prod-admin-1.prod.local.xxxxx.jp:8001/_server_status] が602秒以上応答しません。落ちているか確認してください。
@channel [https://xxx-prod-admin-1.prod.local.xxxxx.jp:8001/_server_status] 655秒でデータの送信を確認しました。

■nginxログ調査
特に、異常はありませんでした。

■php-fpmのログ調査
[06-Feb-2019 10:31:04] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 17 tota
l children

一、CPU利用状況の確認
admin@xxx-prod-admin-1:~$ sar -u  -s 10:30:00 -e 10:45:00
Linux 3.16.0-4-amd64 (xxx-prod-admin-1)     02/06/2019  _x86_64_    (8 CPU)

10:30:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:31:01 AM     all      4.60      0.06      3.85      0.22      0.18     91.08
10:32:01 AM     all     15.13      0.84      2.51      0.20      0.10     81.22
10:33:01 AM     all     15.37      2.95      2.85      1.22      0.12     77.48
10:34:01 AM     all     14.95      2.91      2.74      0.28      0.12     79.00
10:35:01 AM     all     15.29      3.05      3.12      0.27      0.12     78.14
10:36:01 AM     all     15.12      3.09      2.87      0.24      0.13     78.54
10:37:01 AM     all     15.55      2.91      2.81      0.34      0.12     78.26
10:38:01 AM     all     15.48      2.93      2.74      0.24      0.12     78.50
10:39:01 AM     all     15.02      3.05      2.74      0.60      0.13     78.46
10:40:01 AM     all     14.80      2.98      2.76      0.21      0.12     79.11
10:41:01 AM     all     15.78      2.95      2.95      0.39      0.13     77.80
10:42:01 AM     all     15.70      3.03      2.96      0.61      0.13     77.58
10:43:01 AM     all      8.48      0.34      5.32      0.30      0.17     85.39
10:44:01 AM     all      6.08      0.06      4.63      0.27      0.18     88.78
Average:        all     13.39      2.23      3.20      0.38      0.13     80.65

admin@xxx-prod-admin-1:~$ sar -P ALL  -s 10:30:00 -e 10:45:00
Linux 3.16.0-4-amd64 (xxx-prod-admin-1)     02/06/2019  _x86_64_    (8 CPU)

10:30:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:31:01 AM     all      4.60      0.06      3.85      0.22      0.18     91.08
10:31:01 AM       0      6.42      0.18      9.19      0.34      0.29     83.58
10:31:01 AM       1      4.97      0.09      2.99      0.38      0.24     91.34
10:31:01 AM       2      7.00      0.10      3.72      0.29      0.23     88.66
10:31:01 AM       3      4.88      0.03      2.97      0.36      0.22     91.53
10:31:01 AM       4      3.33      0.00      2.48      0.14      0.12     93.93
10:31:01 AM       5      4.12      0.00      3.66      0.12      0.10     92.00
10:31:01 AM       6      3.36      0.07      2.92      0.14      0.12     93.39
10:31:01 AM       7      2.89      0.00      3.13      0.00      0.17     93.81

10:31:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:32:01 AM     all     15.13      0.84      2.51      0.20      0.10     81.22
10:32:01 AM       0      3.32      1.40      5.81      0.60      0.19     88.68
10:32:01 AM       1      3.19      1.26      3.89      0.33      0.16     91.17
10:32:01 AM       2     49.08      0.92      1.01      0.03      0.03     48.93
10:32:01 AM       3     57.18      0.03      2.28      0.31      0.12     40.09
10:32:01 AM       4      1.27      0.81      3.01      0.10      0.07     94.74
10:32:01 AM       5      1.64      1.29      2.49      0.10      0.07     94.41
10:32:01 AM       6      3.30      1.06      1.28      0.10      0.03     94.23
10:32:01 AM       7      1.55      0.00      0.51      0.00      0.08     97.86

10:32:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:33:01 AM     all     15.37      2.95      2.85      1.22      0.12     77.48
10:33:01 AM       0      4.91      3.96      7.89      2.30      0.21     80.72
10:33:01 AM       1      5.07      3.17      4.20      1.34      0.19     86.02
10:33:01 AM       2      3.31      2.13      2.56      0.92      0.12     90.96
10:33:01 AM       3     34.06      2.35      1.48      0.71      0.07     61.34
10:33:01 AM       4      2.15      5.35      2.79      0.99      0.14     88.58
10:33:01 AM       5      1.85      5.37      2.53      2.84      0.12     87.29
10:33:01 AM       6     69.73      1.38      0.86      0.79      0.05     27.20
10:33:01 AM       7      0.49      0.00      0.92      0.02      0.05     98.53

10:33:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:34:01 AM     all     14.95      2.91      2.74      0.28      0.12     79.00
10:34:01 AM       0      4.18      4.10      7.34      0.83      0.23     83.32
10:34:01 AM       1      3.42      4.65      3.99      0.47      0.17     87.30
10:34:01 AM       2     40.12      0.24      0.54      0.12      0.05     58.92
10:34:01 AM       3      3.57      2.64      3.64      0.40      0.17     89.58
10:34:01 AM       4      2.66      6.33      2.71      0.15      0.10     88.04
10:34:01 AM       5      1.73      5.35      2.62      0.22      0.10     89.97
10:34:01 AM       6     61.11      0.19      0.08      0.02      0.02     38.58
10:34:01 AM       7      1.01      0.00      1.27      0.02      0.14     97.56

10:34:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:35:01 AM     all     15.29      3.05      3.12      0.27      0.12     78.14
10:35:01 AM       0      5.67      3.86      9.49      0.75      0.21     80.02
10:35:01 AM       1      4.28      3.93      4.00      0.50      0.17     87.12
10:35:01 AM       2    100.00      0.00      0.00      0.00      0.00      0.00
10:35:01 AM       3      3.75      4.14      4.02      0.60      0.17     87.31
10:35:01 AM       4      1.94      5.34      2.53      0.20      0.12     89.86
10:35:01 AM       5      1.88      5.21      3.02      0.14      0.10     89.65
10:35:01 AM       6      0.29      1.98      0.49      0.02      0.07     97.16
10:35:01 AM       7      2.24      0.00      1.74      0.00      0.17     95.85

10:35:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:36:01 AM     all     15.12      3.09      2.87      0.24      0.13     78.54
10:36:01 AM       0      4.96      3.78      7.59      0.68      0.25     82.74
10:36:01 AM       1      4.75      4.01      4.01      0.54      0.21     86.50
10:36:01 AM       2    100.00      0.00      0.00      0.00      0.00      0.00
10:36:01 AM       3      4.17      4.05      4.17      0.34      0.19     87.09
10:36:01 AM       4      1.80      5.16      2.94      0.15      0.08     89.87
10:36:01 AM       5      1.85      4.16      2.38      0.19      0.12     91.30
10:36:01 AM       6      0.13      3.66      0.75      0.03      0.03     95.39
10:36:01 AM       7      0.92      0.00      1.50      0.00      0.21     97.37

10:36:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:37:01 AM     all     15.55      2.91      2.81      0.34      0.12     78.26
10:37:01 AM       0      4.66      3.42      7.24      0.94      0.21     83.52
10:37:01 AM       1      4.18      3.74      3.89      1.02      0.17     86.99
10:37:01 AM       2      1.40      0.53      0.57      0.15      0.05     97.30
10:37:01 AM       3      7.16      3.92      3.80      0.34      0.17     84.60
10:37:01 AM       4      1.69      6.04      2.80      0.19      0.10     89.19
10:37:01 AM       5      2.41      5.74      3.05      0.17      0.10     88.53
10:37:01 AM       6     99.67      0.00      0.05      0.00      0.00      0.28
10:37:01 AM       7      0.97      0.00      1.49      0.00      0.17     97.37

10:37:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:38:01 AM     all     15.48      2.93      2.74      0.24      0.12     78.50
10:38:01 AM       0      4.13      3.45      6.66      0.72      0.21     84.83
10:38:01 AM       1      4.10      3.72      4.15      0.45      0.14     87.44
10:38:01 AM       2     27.55      0.00      0.60      0.09      0.15     71.62
10:38:01 AM       3      3.98      4.49      3.53      0.27      0.15     87.56
10:38:01 AM       4      5.11      6.03      2.93      0.17      0.10     85.66
10:38:01 AM       5      2.04      5.43      2.90      0.20      0.08     89.35
10:38:01 AM       6     74.24      0.38      0.03      0.00      0.00     25.35
10:38:01 AM       7      0.82      0.00      1.38      0.02      0.14     97.65

10:38:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:39:01 AM     all     15.02      3.05      2.74      0.60      0.13     78.46
10:39:01 AM       0      4.58      3.79      6.91      1.32      0.21     83.19
10:39:01 AM       1      3.86      3.74      3.79      0.78      0.16     87.68
10:39:01 AM       2     73.19      0.05      0.75      0.19      0.15     25.66
10:39:01 AM       3      3.65      4.26      3.56      0.69      0.15     87.69
10:39:01 AM       4      1.54      6.48      2.65      1.09      0.08     88.15
10:39:01 AM       5      2.00      5.44      2.83      0.71      0.10     88.91
10:39:01 AM       6     29.68      0.70      0.23      0.02      0.00     69.36
10:39:01 AM       7      0.85      0.00      1.49      0.02      0.15     97.49

10:39:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:40:01 AM     all     14.80      2.98      2.76      0.21      0.12     79.11
10:40:01 AM       0      3.92      3.31      7.09      0.65      0.23     84.79
10:40:01 AM       1      3.63      3.43      4.10      0.35      0.17     88.32
10:40:01 AM       2     99.98      0.02      0.00      0.00      0.00      0.00
10:40:01 AM       3      3.54      4.61      3.68      0.38      0.16     87.63
10:40:01 AM       4      1.98      4.86      3.08      0.19      0.10     89.80
10:40:01 AM       5      1.91      4.03      2.46      0.14      0.10     91.35
10:40:01 AM       6      0.15      3.69      0.78      0.03      0.05     95.29
10:40:01 AM       7      0.95      0.00      1.22      0.02      0.17     97.64

10:40:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
10:41:01 AM     all     15.78      2.95      2.95      0.39      0.13     77.80
10:41:01 AM       0      4.45      2.81      7.13      0.61      0.21     84.79
10:41:01 AM       1      4.82      4.41      4.89      0.59      0.16     85.14
10:41:01 AM       2      5.78      0.20      0.59      0.08      0.12     93.22
10:41:01 AM       3      4.09      4.16      3.78      1.03      0.17     86.76
10:41:01 AM       4      5.76      5.98      3.19      0.68      0.08     84.30
10:41:01 AM       5      2.48      5.95      2.79      0.15      0.12     88.50
10:41:01 AM       6     95.12      0.20      0.08      0.00      0.00      4.60
10:41:01 AM       7      1.36      0.00      1.46      0.02      0.15     97.01


上記の出力情報から見て、CPU全体の利用率（%userと%iowait）は全然高くなくて、IOのボトルネックも見えないです。
さらに、空いている比率（%idle）はやや高いので、CPUの状態はそんなに忙しくないことが判断できます。

★しかし、個別のコアが使用100%の状況がありますので、CPU利用不平均の問題が存在するようです。
★Nginxの設定を確認する必要です。多コアを利用しているかどうか重点確認★

★なお、この状態でクライアントからのリクエストに対する対応は遅くなったり、あるいは全然レスポンスできない場合には、
★新しいプロセスあるいはスレッドを作成しようと、メモりを取れない可能性があります。つもり、メモり不足の可能性があります。
★引き続き、メモリの状況をみましょうか。

二、メモり利用状況の確認
＞admin@xxx-prod-admin-1:~$ sar -r -s 10:00:00 -e 11:00:00
10:00:01 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact kbdirty
10:31:01 AM 1028816   62015004  98.37    1727516   5232536  59865876 94.96   53217080 3477276 1824
10:31:01 AM 1028816   62015004  98.37    1727516   5232536  59865876 94.96   53217080 3477276 1824
10:32:01 AM 421672    62622148  99.33    1727808   4503492  63542396 100.79  53956716 3048880 11332
10:33:01 AM 477336    62566484  99.24    1728372   4346084  63666944 100.99  53987720 2960576 29588
10:34:01 AM 633764    62410056  98.99    1729020   4319368  63528308 100.77  53854144 2938912 41792
10:35:01 AM 620860    62422960  99.02    1729416   4204500  63646192 100.96  53921720 2884616 26276
10:36:01 AM 652012    62391808  98.97    1730052   4221464  63646624 100.96  53902536 2879608 42532
10:37:01 AM 662140    62381680  98.95    1730732   4239528  63603240 100.89  53897620 2869780 6180
10:38:01 AM 693356    62350464  98.90    1731172   4213260  63550428 100.80  53883012 2854220 9484
10:39:01 AM 639264    62404556  98.99    1732112   4237880  63656900 100.97  53940212 2851840 1052
10:40:01 AM 738320    62305500  98.83    1732876   4262120  63493596 100.71  53849576 2849048 6264
10:41:01 AM 844676    62199144  98.66    1733520   4088796  63503072 100.73  53811724 2783744 5736
10:42:01 AM 1011556   62032264  98.40    1733984   3899372  63513808 100.75  53733204 2703324 1088
10:43:01 AM 1452140   61591680  97.70    1734492   3903736  62407536 98.99   53379576 2698600 2588
10:44:01 AM 1954796   61089024  96.90    1734660   3904624  61124208 96.96   52982180 2696536 3712
10:45:01 AM 2412992   60630828  96.17    1734824   3905572  59921140 95.05   52623116 2693016 1368

上記の情報から見て、メモリの使用率（ %memused ）は相当高いです。
さらに、10:32分から〜10:42分の間にスワップ領域を含むメモリ（%commit）全体使用量は100%を超えてしまいます。
システムのスワップ設定を確認した結果、下記のようにできるだけ、物理メモリを使用するように設定されております。
＞admin@xxx-prod-admin-1:~$ cat /proc/sys/vm/swappiness
＞0　　⇨　　ゼロの意味はできるだけ、物理メモリを使うことです。

この状態でリクエストが急に殺到した場合に、処理プロセスは使用切れ、新プロセスはメモリを確保できず、
なかなか作成できないことは原因になる可能性は排除されません。

メモリはそんなに消耗されたのか、具体的に、誰によって、消耗されたのか、確定する必要です。

三、メモりリークの可能性調査
■Nginxの設定ファイル確認（ nginx.conf）
不適切な数値は特にないです。Nginxのメモりリークの可能性を排除します。

プロセスの関連設定をみると、最初起動するプロセス数は自動です。１プロセスは最大、4000コネクションが処理できます。
ただし、「 worker_cpu_affinity auto;」の設定はなし、１コアしか利用できません。これはCPUの利用不平均の可能原因じゃないかと思います。

worker_processes auto；
events {
  worker_connections 4000;
  multi_accept on;
}

■PHPーFPMの設定ファイル確認
＞root@docker-prod-admin:/# ls -latr /etc/php/7.0/fpm/pool.d
＞root@docker-prod-admin:/# cat /etc/php/7.0/fpm/pool.d/www.conf
pm = dynamic
pm.max_children=200
pm.start_servers=5
pm.min_spare_servers=5
pm.max_spare_servers=10
pm.max_requests=10000

上記のPHPーFPMの設定から見て、メモりリークに導く不適切な設定はないので、メモりリークを排除します。
しかし、PHPーFPMの同時処理上限は200しかないので、ちょっと不足な感じですよね？？？
なので、200以上のコネクション要求は処理できない可能性があります。

引き続き、一番メモリを消耗しているプロセスを確認しましょうか。

■一番メモリを消耗しているプロセスの確定（メモリの使用量で降順表示）
＞admin@xxx-prod-admin-1:~$ top
＞top - 15:36:44 up 24 days, 6:10, 1 user, load average: 1.11, 1.28, 1.28
＞Tasks: 202 total, 3 running, 199 sleeping, 0 stopped, 0 zombie
＞%Cpu(s): 6.2 us, 4.4 sy, 0.0 ni, 87.0 id, 0.5 wa, 0.0 hi, 1.9 si, 0.1 st
＞KiB Mem: 63043820 total, 62180820 used, 863000 free, 1764524 buffers
＞KiB Swap: 0 total, 0 used, 0 free. 4726120 cached Mem
PID   USER   PR NI VIRT    RES    SHR    S %CPU %MEM TIME+     COMMAND
693   root   20 0  36.461g 0.033t 2552   S 45.9 56.9 3145:54   mount.objective
699   root   20 0  13.437g 0.011t 2604   S 0.0  19.1 683:20.01 mount.objective
710   root   20 0  3295736 1.194g 2624   S 0.3  2.0  707:44.07 mount.objective
23094 tvuser 20 0  625452  452328 7080   R 3.0  0.7  12:53.75  nginx
23091 tvuser 20 0  624924  451792 7080   S 0.7  0.7  1:34.60   nginx
23092 tvuser 20 0  595872  422748 7080   S 0.0  0.7  2:14.64   nginx
23093 tvuser 20 0  594352  421228 7080   S 1.0  0.7  5:14.92   nginx
23085 tvuser 20 0  592376  419252 7080   S 0.0  0.7  0:32.50   nginx
2797  root   20 0  584108  416740 13336  S 0.0  0.7  0:02.65   nginx
23089 tvuser 20 0  588440  415316 7080   S 0.0  0.7  0:44.10   nginx
23090 tvuser 20 0  586940  413812 7080   S 0.0  0.7  1:16.61   nginx
23081 tvuser 20 0  586604  413464 7080   S 0.0  0.7  0:23.88   nginx
2796  root   20 0  578412  411388 13188  S 0.0  0.7  0:02.12   nginx
23994 tvuser 20 0  581136  408164 7312   S 0.7  0.6  1:33.19   nginx
23998 tvuser 20 0  581100  408156 7312   S 1.3  0.6  9:58.35   nginx
23996 tvuser 20 0  580988  407984 7312   S 0.3  0.6  1:48.99   nginx
23993 tvuser 20 0  580768  407940 7340   S 0.0  0.6  1:12.76   nginx
23992 tvuser 20 0  580820  407872 7312   S 0.0  0.6  0:57.52   nginx
23995 tvuser 20 0  580916  407844 7312   S 0.3  0.6  2:07.39   nginx
23991 tvuser 20 0  580856  407808 7312   S 0.0  0.6  0:44.70   nginx
23997 tvuser 20 0  580700  407736 7312   S 1.0  0.6  4:09.17   nginx
213   root   20 0  176588  122436 122136 S 0.0  0.2  3:15.21   systemd-journal
21803 root   39 19 1277224 58648  8720   S 1.7  0.1  4:32.48   aws
21750 root   39 19 1128992 52944  8744   S 1.7  0.1  4:16.24   aws
13622 tvuser 20 0  467164  50664  41076  S 1.0  0.1  0:03.97   php-fpm7.0
12681 tvuser 20 0  467656  50320  40096  S 0.7  0.1  0:04.85   php-fpm7.0
12682 tvuser 20 0  466988  49296  39948  S 0.7  0.1  0:04.77   php-fpm7.0
12679 tvuser 20 0  467292  46236  36548  S 1.0  0.1  0:03.11   php-fpm7.0
12664 tvuser 20 0  466928  45412  36120  S 0.7  0.1  0:04.00   php-fpm7.0
412   root   20 0  752932  44256  4500   S 1.0  0.1  246:29.07 agent.pl
2786  root   20 0  461268  42944  34592  S 0.0  0.1  2:00.04   php-fpm7.0
12680 tvuser 20 0  466912  42808  33428  S 0.3  0.1  0:03.54   php-fpm7.0
2785  root   20 0  461268  42600  34248  S 0.0  0.1  1:49.76   php-fpm7.0
17901 tvuser 20 0  466840  42380  33136  S 0.3  0.1  0:02.52   php-fpm7.0
17249 tvuser 20 0  466912  40308  30996  S 1.0  0.1  0:01.75   php-fpm7.0
21437 tvuser 20 0  464028  36188  27264  S 2.0  0.1  0:00.35   php-fpm7.0

上記の出力情報から見て、mount.objectiveの方は全体の80%ぐらい消耗していることがわかりました。
時間の経つによって、さらに増加する可能性があります。なお、nginxとphp-fpm7にはメモりリークがないことが確定できます。

四、結論
■CPU方面
Nginxの設定はデフォルト１コアしか利用しないので、CPU使用不平均の可能性が存在します。

推奨設定：
worker_processes auto
worker_cpu_affinity auto;

■メモり方面
mount.objectiveはメモりの使用量は大きすぎなので、他のプロセスに圧迫する可能性があります。
mount.objectiveの物理メモりの使用量を制限することで、ある程度改善できるじゃないかと思います。

■PHPーFPMの処理プロセス不足
PHPーFPM現在、同時、最大200のリクエストしか処理できないので、
それ以上の場合はずっと待ってしまいまい、タイムアウトしたら、コネクションエラーになる可能性があります。

推奨設定：
Nginxの「worker_connections」に合わせて、設定した方がいいと思います。
でも、Nginxの「worker_connections 4000;」はちょっと大きいので、小さく調整した方がいいと思います。

例：
Nginx:
worker_connections 2000;
PHPーFPM:
pm.max_children = worker_processes * worker_connections/2