現象：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