Laravelのスケジューラーを秒単位で使うときのcronの注意点
本当に、この問題を解決するのに10時間も苦労した。 まず簡単に説明すると。 このように、Laravelのスケジューラーを秒単位で設定する場合がある。 このとき、ドキュメントには次のように書かれている。 このように設定するように書かれている。 ところが、ここには大きな問題が1つある。 schedule:runのプロセスが
GGAMI
本当に、この問題を解決するのに10時間も苦労した。
まず簡単に説明すると。
本当に、この問題を解決するのに10時間も苦労した。 まず簡単に説明すると。 このように、Laravelのスケジューラーを秒単位で設定する場合がある。 このとき、ドキュメントには次のように書かれている。 このように設定するように書かれている。 ところが、ここには大きな問題が1つある。 schedule:runのプロセスが
本当に、この問題を解決するのに10時間も苦労した。
まず簡単に説明すると。
このように、Laravelのスケジューラーを秒単位で設定する場合がある。
このとき、ドキュメントには次のように書かれている。
SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
* * * * * php /var/www/artisan schedule:run > /tmp/cron.last 2>&1このように設定するように書かれている。
ところが、ここには大きな問題が1つある。
schedule:runのプロセスが起動し、そこでは1分間、1秒ごとに処理が繰り返し実行される。
Laravelのコードでは、そのような実装になっている。
最初は、onOneServerの問題なのか？ runInBackgroundの問題なのか？ command？ job？ そのあたりをデバッグしたが、問題はそこでは発生していなかった。 そこで、PHP自体が実行されているか確認したところ、そもそも実行すらされていなかった。
最初はAlpine Linuxのイメージにdcronをインストールして使っていた。 dcronの問題かと思い、dcronを削除してBusyBox cronに切り替えてみたりもした。
しかし、BusyBox cronに切り替えても、やはり解決しなかった。
そこで、最終的にcronのログを取ってみた。
cat cron.log
crond: crond (busybox 1.37.0) started, log level 8
crond: USER cron pid 86 cmd php /var/www/artisan schedule:run > /tmp/cron.last 2>&1
crond: USER cron pid 87 cmd echo "Cron is working: $(date)" >> /tmp/cron_test.log
crond: user cron: process already running: php /var/www/artisan schedule:run > /tmp/cron.last 2>&1
crond: USER cron pid 896 cmd echo "Cron is working: $(date)" >> /tmp/cron_test.log
crond: USER cron pid 904 cmd php /var/www/artisan schedule:run > /tmp/cron.last 2>&1
crond: USER cron pid 905 cmd echo "Cron is working: $(date)" >> /tmp/cron_test.logすると、次のような結果が得られた。
crond: user cron: process already running
プロセスが重複して実行されないようになっていたのだ…
ああ…今になってこれに気づくとはㅠㅠ
そこで調べてみたところ
まさにこのようにチェックしていて、すでにプロセスが実行中なら重複して実行しないことが確認できた。 本当に…cronがPIDの重複実行を抑止するってことを知った。あれ？知ってたのに忘れてたのかなㅡ. ㅡ？
ああ…それで、解決方法はというと…
SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
* * * * * php /var/www/artisan schedule:run > /tmp/cron.last 2>&1 &末尾に&を付けてバックグラウンド実行に変更したことで、解決できた。
以前は末尾に&を付けて使っていたのだが、前回、秒単位のスケジューラーが追加されたときに、ドキュメントを見て&を外して使っていた。それが問題だったようだ。
では、なぜこの問題が発生するのか？？ php schedule:runは、59秒を最後の時点として終了しなければならない。
protected function repeatEvents($events)
{
$hasEnteredMaintenanceMode = false;
while (Date::now()->lte($this->startedAt->endOfMinute())) {
foreach ($events as $event) {
if ($this->shouldInterrupt()) {
return;
}
if (! $event->shouldRepeatNow()) {
continue;
}
$hasEnteredMaintenanceMode = $hasEnteredMaintenanceMode || $this->laravel->isDownForMaintenance();
if ($hasEnteredMaintenanceMode && ! $event->runsInMaintenanceMode()) {
continue;
}
if (! $event->filtersPass($this->laravel)) {
$this->dispatcher->dispatch(new ScheduledTaskSkipped($event));
continue;
}
if ($event->onOneServer) {
$this->runSingleServerEvent($event);
} else {
$this->runEvent($event);
}
$this->eventsRan = true;
}
Sleep::usleep(100000);
}
}しかし、これを2秒ごとに実行するようにしても、2、4、6、8秒ごとに実行されるわけではない。
commandを読み込むたびに少し遅延が発生するため、そのようなときには
2、4、7、9、11、12、14というように、実行時刻が途中でずれることがある。
そうすると、59秒に実行されるcommandが1秒以内にすべて完了しなければ、
そのプロセスは59秒に終了するはずだが、59秒に実行されたコマンドがまだ完了していないため、
cronでcrond: user cron: process already runningの問題が発生する。
結局、この問題を避けるには、スケジューラーで実行するときに必ずrunInBackground()を使うのは当然として、
schedule:runを使う場合は、末尾に&を付けてバックグラウンドで実行する必要がある。
重複の管理はコード上で制御しなければならない。
Schedule::command(Test2Command::class)->everyTwoSeconds()->onOneServer()->withoutOverlapping()->runInBackground();withoutOverlapping()を使うということだ。
ちなみに、すべてjobにするにせよ、commandをdispatchしてjobに渡すにせよ、commandが40個、50個になった時点で、processが60秒を超えないという保証はない。
もちろん、この問題はBusyBox cronやdcronだけの問題かもしれない。 Alpine Linuxのイメージに移行したことで発生した可能性もある。
いずれにせよ、schedule:runを使ってスケジューラーを動かすなら、バックグラウンド実行をおすすめする。