Laravelのタイマー処理に関しては無条件に非同期に実行されるものと思っていましたが、実は少々複雑な状況であることが分かりましたので、改めて整理しておきたいと思います。

Laravelのタイマー処理

Laravelでタイマー処理（タスクスケジュール）を行いたい場合は、以下のようにします。

まず、「app/Console/Commands」に期待する処理内容を含むコマンドを作成します。

<?php

namespace App\Console\Commands;

use Illuminate\Console\Command;

class TimerTest1 extends Command
{
    protected $signature = 'command:＜コマンド名＞';

    protected $description = '＜コマンドの概要説明＞';

    public function __construct()
    {
        parent::__construct();
    }

    public function handle()
    {
        // 期待する処理内容
    }
}

上記を「app/Console/Kernel.php」から実行するよう設定します。

<?php

namespace App\Console;

use Illuminate\Console\Scheduling\Schedule;
use Illuminate\Foundation\Console\Kernel as ConsoleKernel;

class Kernel extends ConsoleKernel
{
    protected $commands = [
        //
    ];

    protected function schedule(Schedule $schedule)
    {
        $schedule->command('command:timer_test_1');
    }

    protected function commands()
    {
        $this->load(__DIR__.'/Commands');

        require base_path('routes/console.php');
    }
}

最後に上記設定内容が定期的に呼び出されるようcronに設定します。

* * * * * cd ＜Laravel環境へのパス＞ && php artisan schedule:run >> /dev/null 2>&1

つまりは、毎分「App\Console\Kernel」クラスを呼び出しつつ、同クラス内の「schedule」メソッドで実行すべきコマンドを選択的に実行する訳です。

「選択的」にと書きましたが、「schedule」メソッドでは実行タイミングの指定ができます。
例えば1時間に一回実行したい場合は以下のように書くことで、「schedule」メソッド自体は毎分呼び出されながら、「timer_test_1」コマンドを実行するのは1時間に一回になります。

$schedule->command('command:timer_test_1')->hourly();;

実行タイミングとしては様々な指定が可能ですが、この辺は本記事の趣旨からは外れますので、詳しくはGoogle先生に聞いてください。

非同期性の確認

上記のように「App\Console\Kernel」クラスの「schedule」メソッドから期待する処理内容のコマンドを実行するとして、その実行は同期的に行われるか、非同期的に行われるかを確認してみます。

「schedule」メソッドの内容を以下のようにします。

        self::log('schedule start', null);
        $schedule->command('command:timer_test_1');
        self::log('schedule end', null);

「self::log」は独自に用意したログメソッドです。

同様に「App\Console\Commands\TimerTest1」クラスの「handle」メソッドを以下のようにします。

        $startTime = date('Y-m-d H:i:s');
        self::log('command 1 start', $startTime);
        sleep(10);
        self::log('command 1 end', $startTime);

処理完了までに10秒かかるようにしてみました。

実行結果は以下の通り。

2022/02/06 09:27:01.282092 DEBUG: [x] schedule start
2022/02/06 09:27:01.283893 DEBUG: [x] schedule end
2022/02/06 09:27:01.541192 DEBUG: [x] command 1 start 2022-02-06 09:27:01
2022/02/06 09:27:11.542021 DEBUG: [x] command 1 end 2022-02-06 09:27:01

「App\Console\Kernel」クラスの「schedule」メソッドは「App\Console\Commands\TimerTest1」クラスの実行を待ち合わせずに完了しています。つまりコマンドは非同期に実行されていることになります。

この辺は予定通りでした。

では、実行対象が複数存在した場合はどうでしょう？

新たに「App\Console\Commands\TimerTest2」クラスを用意し、「handle」メソッドを以下のようにします。

        $startTime = date('Y-m-d H:i:s');
        self::log('command 2 start', $startTime);
        self::log('command 2 end', $startTime);

「App\Console\Kernel」クラスの「schedule」メソッドは以下のように変更します。

        self::log('schedule start', null);
        $schedule->command('command:timer_test_1');
        $schedule->command('command:timer_test_2');
        self::log('schedule end', null);

上記実行結果は以下の通り。

2022/02/06 09:56:02.249527 DEBUG: [x] schedule start
2022/02/06 09:56:02.251527 DEBUG: [x] schedule end
2022/02/06 09:56:02.498800 DEBUG: [x] command 1 start 2022-02-06 09:56:02
2022/02/06 09:56:12.499966 DEBUG: [x] command 1 end 2022-02-06 09:56:02
2022/02/06 09:56:12.748293 DEBUG: [x] command 2 start 2022-02-06 09:56:12
2022/02/06 09:56:12.748619 DEBUG: [x] command 2 end 2022-02-06 09:56:12

「App\Console\Kernel」クラスと各コマンドの実行は非同期に行われますが、コマンド相互では先に実行しているコマンドの完了を待ち合わせて次のコマンドが実行されるよう、同期的に制御されているようです。

この点は予想外でした。

個人的にはタイマー実行させたい処理内容が複数存在する場合でもほとんどが相互に依存関係がないものですし、もし依存関係がある処理内容であれば1つのコマンド内でそれらをまとめて実行するようにしているので、上記のように複数コマンドが同期的に実行されるありがたみが今ひとつ分かりません。
逆に上記のようになっていることで、起動順が後の方のコマンドの実行タイミングが本来期待された時刻よりも遅れてしまうので、デメリットの方は簡単に思いつくのですが…

コマンドの非同期実行

では、「schedule」メソッドから複数コマンドを相互に非同期に実行したい場合はどうするかと言うと、「runInBackground」メソッドを使用します。

        self::log('schedule start', null);
        $schedule->command('command:timer_test_1')->runInBackground();
        $schedule->command('command:timer_test_2')->runInBackground();
        self::log('schedule end', null);

実行結果は以下の通り。

2022/02/06 10:12:02.297901 DEBUG: [x] schedule start
2022/02/06 10:12:02.299729 DEBUG: [x] schedule end
2022/02/06 10:12:02.617093 DEBUG: [x] command 1 start 2022-02-06 10:12:02
2022/02/06 10:12:02.639839 DEBUG: [x] command 2 start 2022-02-06 10:12:02
2022/02/06 10:12:02.640129 DEBUG: [x] command 2 end 2022-02-06 10:12:02
2022/02/06 10:12:02.897087 DEBUG: [x] schedule start
2022/02/06 10:12:02.898893 DEBUG: [x] schedule end
2022/02/06 10:12:12.618273 DEBUG: [x] command 1 end 2022-02-06 10:12:02
2022/02/06 10:12:12.860450 DEBUG: [x] schedule start
2022/02/06 10:12:12.862174 DEBUG: [x] schedule end

非同期的に実行されるようになった結果としてログは見難くなりましたが、「timer_test_1」の完了を待たずに「timer_test_2」が起動されるようになったのは分かるかと思います。

謎なのは、それぞれのコマンド完了時に再度「schedule」メソッドが実行された記録が残っている点です。
同実行時に再度コマンドが多重に実行されてしまうと言うようなことにはなっていないようですが、なぜこのような振る舞いになっているかはよく分かりません。

多重実行の抑止

前述のログにおいて、「schedule」メソッドが想定外に複数回呼び出されているらしき痕跡が発見されました。
ここでは誤ってコマンドが多重に実行されていないことは確認できましたが、例えば毎分呼び出しているコマンドの実行時間が1分を超えてしまった場合、同一コマンドが多重に実行される形になることはあり得ます。

コマンドの処理内容によっては多重に実行されると都合が悪いものもあります。そのような場合は「withoutOverlapping」メソッドを使用します。

確認のため、「App\Console\Commands\TimerTest1」の「handle」メソッドを以下のように変更します。

        $startTime = date('Y-m-d H:i:s');
        self::logDebug('command 1 start', $startTime);
        sleep(70);
        self::logDebug('command 1 end', $startTime);

「schedule」メソッドは以下のように変更します。

        self::log('schedule start', null);
        $schedule->command('command:timer_test_1')->runInBackground()->withoutOverlapping();
        $schedule->command('command:timer_test_2')->runInBackground();
        self::log('schedule end', null);

結果は以下の通り。

2022/02/06 10:34:01.749495 DEBUG: [x] schedule start
2022/02/06 10:34:01.751288 DEBUG: [x] schedule end
2022/02/06 10:34:02.010568 DEBUG: [x] command 1 start 2022-02-06 10:34:01
2022/02/06 10:34:02.019117 DEBUG: [x] command 2 start 2022-02-06 10:34:02
2022/02/06 10:34:02.019380 DEBUG: [x] command 2 end 2022-02-06 10:34:02
2022/02/06 10:34:02.245999 DEBUG: [x] schedule start
2022/02/06 10:34:02.247830 DEBUG: [x] schedule end
2022/02/06 10:35:02.120284 DEBUG: [x] schedule start
2022/02/06 10:35:02.122275 DEBUG: [x] schedule end
2022/02/06 10:35:02.375262 DEBUG: [x] command 2 start 2022-02-06 10:35:02
2022/02/06 10:35:02.375590 DEBUG: [x] command 2 end 2022-02-06 10:35:02
2022/02/06 10:35:02.605442 DEBUG: [x] schedule start
2022/02/06 10:35:02.607347 DEBUG: [x] schedule end
2022/02/06 10:35:12.011435 DEBUG: [x] command 1 end 2022-02-06 10:34:01
2022/02/06 10:35:12.256316 DEBUG: [x] schedule start
2022/02/06 10:35:12.258108 DEBUG: [x] schedule end
2022/02/06 10:36:01.438651 DEBUG: [x] schedule start
2022/02/06 10:36:01.440495 DEBUG: [x] schedule end
2022/02/06 10:36:01.720559 DEBUG: [x] command 1 start 2022-02-06 10:36:01
2022/02/06 10:36:01.729732 DEBUG: [x] command 2 start 2022-02-06 10:36:01
2022/02/06 10:36:01.730008 DEBUG: [x] command 2 end 2022-02-06 10:36:01
2022/02/06 10:36:01.958415 DEBUG: [x] schedule start
2022/02/06 10:36:01.960211 DEBUG: [x] schedule end
2022/02/06 10:37:01.697863 DEBUG: [x] schedule start
2022/02/06 10:37:01.699637 DEBUG: [x] schedule end
2022/02/06 10:37:01.941760 DEBUG: [x] command 2 start 2022-02-06 10:37:01
2022/02/06 10:37:01.942265 DEBUG: [x] command 2 end 2022-02-06 10:37:01
2022/02/06 10:37:02.215280 DEBUG: [x] schedule start
2022/02/06 10:37:02.217737 DEBUG: [x] schedule end
2022/02/06 10:37:11.721607 DEBUG: [x] command 1 end 2022-02-06 10:36:01
2022/02/06 10:37:11.976012 DEBUG: [x] schedule start
2022/02/06 10:37:11.977954 DEBUG: [x] schedule end

「timer_test_1」に関しては「10:34:02」に実行され、「10:35:12」に終了しています。その間「10:35:02」にも「schedule」メソッドは実行されていますが、ここでは「timer_test_1」の実行は行われず、次の「10:36:01」の「schedule」メソッド実行時には再度「timer_test_1」が実行されています。

一方で、「timer_test_2」の実行は「timer_test_1」の状況に影響されずに粛々と行われています。

総括

もともと「schedule」メソッドからの各コマンド実行は完全に非同期であるとの思い込みでタイマー処理を行っていたので、実行タイミングが遅れるケースがありました。
「schedule」メソッドとコマンドの実行は非同期でありながら、コマンド相互の実行は同期（順次）実行になっている点は少々罠っぽく思いますが…

多重実行抑止（withoutOverlapping）は以前から必要に応じて採用していたのですが、ここに非同期（runInBackground）を加えた挙動を明確に確認できたと言う点で、今回の作業は意味があったかと思います。

ただ、非同期コマンド完了時に逐一「schedule」メソッドが呼ばれている点だけは未だに謎です。