created: 2019-06-20 24:00, tags: laravel, server, supervisor,

Laravel と supervisor で設定が悪いと CPU 負荷が酷い

特に面白みはないけど、負荷を気にしない人が設定すると酷い事になる話。

ここで出しているデータ自体は後で再現用に用意したものなので実際とは違う (大体似た感じだけど)。

キッカケ

調べるはめになったのは、先日開発中のシステムのステージングが遅すぎてなんなんだろうと調べたのが始まり (ステージングのアクセス権を貰ったのが最近で、遅いという話自体はずっと前からあった)。

調査

サーバの WEB レスポンスが非常に遅いという事で、とりあえず SSH でログインし、top で確認。

$ top -c

-c オプションを付けるのは、詳細なコマンドオプション等が見たいため。実際今回のケースは Laravel の queue の実行処理に悪い点があり、-c を付けない場合は単に php の実行プロセスとしか表示されない。

top - 04:30:55 up 3 days,  8:43,  3 users,  load average: 5.45, 4.57, 2.98
Tasks: 179 total,   1 running, 136 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.7 us, 22.0 sy,  0.0 ni, 76.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   493016 total,     7144 free,   376804 used,   109068 buff/cache
KiB Swap:  1003516 total,   324772 free,   678744 used.   103420 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
10427 vagrant   20   0  358856  41500  23700 S  3.0  8.4   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge1                                                                        
10417 vagrant   20   0  358856  41508  23708 S  2.6  8.4   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge1                                                                        
10418 vagrant   20   0  358856  41820  24020 S  2.6  8.5   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge2                                                                        
10421 vagrant   20   0  358856  41512  23712 S  2.6  8.4   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge2                                                                        
10424 vagrant   20   0  358856  41812  24012 S  2.6  8.5   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge3                                                                        
10425 vagrant   20   0  358856  41596  23796 S  2.6  8.4   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge3                                                                        
10426 vagrant   20   0  358856  41560  23756 S  2.6  8.4   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge4                                                                        
10429 vagrant   20   0  358856  41616  23812 S  2.6  8.4   0:00.42 /usr/bin/php7.3 artisan queue:listen --queue=hoge4

この内容を見ると、load average が異常に高く、5 を叩き出している (これはローカルで同様の状態を表現したもので、実際遭遇したものも 5 強だった)。プロセスを見ると CPU リソースを食っていたのは queue 用に上げているプロセスだった (queue:listen を使用していた)。

Laravel では、supervisor を使ってプロセスの管理を推奨しているため、当 PJ も同様の方法でセットアップしていた。その時の conf がこれ。

[program:laravel-queue-1]
command=php /home/vagrant/laravel/artisan queue:listen --queue=hoge1

process_name=%(program_name)s_%(process_num)02d
autostart=true
autorestart=true
stopasgroup=true
killasgroup=true
user=vagrant
numprocs=2

要所で変更はしているが、このファイルが 1~4 まで 4 つあり、queue をそれぞれのファイルで 1 つ指定していた。また、supervisor の conf で numprocs を 2 としているため、4 * 2 で 8 つのプロセスを上げる設定となる。その上、queue:listen を使っているため、フレームワークの再起動コストが重く、結果 load average が高くなるという現象が発生していた。

下記ページのデーモンキューリスナーを参照

Laravel 5.1 キュー (5.1 は貼り間違いではない)

解決策

今回の問題は下記 3 点。

numprocs を不用意に 2 にしていた
supervisor のハンドルををキュー毎に作っていた
work ではなく listen を使っていた

そのため、上記をそれぞれ実行環境のスペックや要求に合わせて調整する。今回はステージングという事もあり、それ程潤沢なスペックを持つサーバではない上に、キューの処理を裁く事に神経質になる必要がない環境である (キューに対して高負荷がかかる事は意図的に実行しない限りない)。

そのため、numprocs を 1 に、supervisor のハンドルを 1 つに、queue:listen を止め、queue:work を使うように、それぞれ変更した。

変更すると下記のようになる。

[program:worker-326007-1]
command=php /home/vagrant/laravel/artisan queue:listen --queue=hoge1,hoge2,hoge3,hoge4

process_name=%(program_name)s_%(process_num)02d
autostart=true
autorestart=true
stopasgroup=true
killasgroup=true
user=vagrant
numprocs=1

top - 06:15:38 up 3 days,  9:52,  3 users,  load average: 0.00, 0.02, 0.65
Tasks: 156 total,   1 running, 113 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.7 sy,  0.0 ni, 99.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   493016 total,   143084 free,   196636 used,   153296 buff/cache
KiB Swap:  1003516 total,   429916 free,   573600 used.   283396 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND 
  741 redis     20   0   51444    144      0 S  0.3  0.0   6:39.60 /usr/bin/redis-server 127.0.0.1:6379                                                                                                                                       
  827 mysql     20   0 1163452  33840      0 S  0.3  6.9   5:07.49 /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid                                                                                                             
 4205 vagrant   20   0  358848  41408  23556 S  0.3  8.4   0:01.06 php /home/laravel/artisan queue:work --queue=hoge1,hoge2,hoge3,hoge4                                                                                       
 4370 vagrant   20   0   44236   4000   3312 R  0.3  0.8   0:00.07 top -c                                                                                                                                                                     
    1 root      20   0  225464   4812   3136 S  0.0  1.0   0:34.44 /sbin/init                                                                                                                                                                 
    2 root      20   0       0      0      0 S  0.0  0.0   0:00.00 [kthreadd]                                                                                                                                                                 
    4 root       0 -20       0      0      0 I  0.0  0.0   0:00.00 [kworker/0:0H]                                                                                                                                                             
    6 root       0 -20       0      0      0 I  0.0  0.0   0:00.00 [mm_percpu_wq]

supervisor を再起動して設定を読み込み直し、10 分程度放置した状態がこちら。 load average が見事に 0.00 まで下がっている。

当該のサーバへのアクセスが遅い問題もこの件を解決する事で無事解決された。

biwakonbu.dev

Laravel と supervisor で設定が悪いと CPU 負荷が酷い

キッカケ

調査

解決策