カンリーにおける店舗数の増加と処理時間短縮への取り組み

2024年7月24日 11:31

はじめまして！株式会社カンリーエンジニア部の有山です。
普段は「カンリー」の開発を行っています。

「カンリー」はおかげさまで 73,000 店舗を超える店舗に導入いただいており、急速に成長してきました。
今後ともミッションである「店舗経営を支える世界的なインフラをつくる」の達成に向けてより良いプロダクト作りに励んでまいります！

そんな「カンリー」ですが、急速な成長を遂げる一方で、店舗数の増加に伴う処理の増加への対策が課題となっていました。
今回は、過去、店舗数が増加していく中で実施した対策と躓いた点について紹介したいと思います。

「カンリー」とは

「カンリー」は、Google ビジネスプロフィールや Yahoo! プレイスなど複数の店舗情報やクチコミを一括管理・分析することで、管理・運用コストを削減し、集客効果をあげることができるツールです。
詳細は下記サービスページをご参照ください。

また、開発言語としては PHP (Laravel) を利用しています。

処理時間短縮への取り組み

「カンリー」には様々なバッチ処理があり、中には「カンリー」に登録されているすべての店舗を対象に処理を実行するものも存在します。
そういったバッチ処理は通常夜間帯に実施しますが、店舗数が増加する中で夜間に処理を終えられない可能性が出てきました。

そこで処理時間の短縮を目的として、PHP の exec 関数を利用したマルチプロセス処理に注目しました。
具体的には、以下のようにして artisan コマンドを並行に実行することを検討します。

<?php

namespace App\Console\Commands;

use Illuminate\Console\Command;
use Illuminate\Support\Facades\Log;
use Throwable;

class OutputStores extends Command
{
    /**
     * The name and signature of the console command.
     *
     * @var string
     */
    protected $signature = 'app:output-stores {--S|store=* : Store ID}';

    /**
     * The console command description.
     *
     * @var string
     */
    protected $description = 'Output stores';

    /**
     * Execute the console command.
     */
    public function handle()
    {
        try {
            $storeIds = $this->option('store');
            Log::info(count($storeIds));
            sleep(10);
        } catch (Throwable $e) {
            Log::error($e);
        }
    }
}

<?php

namespace App\Console\Commands;

use App\Models\Store;
use Carbon\Carbon;
use Illuminate\Console\Command;
use Illuminate\Support\Facades\Log;
use Throwable;

class OutputStoresWithMultiprocessing extends Command
{
    /**
     * The name and signature of the console command.
     *
     * @var string
     */
    protected $signature = 'app:output-stores-with-multiprocessing';

    /**
     * The console command description.
     *
     * @var string
     */
    protected $description = 'Output stores';

    /**
     * Execute the console command.
     */
    public function handle()
    {
        try {
            $startTime = Carbon::now();
            Log::info('Start: ' . $startTime->format('Y-m-d H:i:s'));
            $numberOfDivisions = 10;
            $stores = Store::all()->pluck('id')->toArray();
            $storeIds = [];
            for ($i = 0; $i < $numberOfDivisions; $i++) {
                foreach ($stores as $key => $storeId) {
                    if ($key % $numberOfDivisions === $i) {
                        if (!isset($storeIds[$i])) {
                            $storeIds[$i] = [];
                        }
                        $storeIds[$i][] = $storeId;
                    }
                }
            }
            $cmd = '';
            $prefix = 'php artisan app:output-stores';

            for ($i = 0; $i < $numberOfDivisions; $i++) {
                $storeIdsStr = implode(' -S ', $storeIds[$i]);
                $cmd .= $prefix . ' -S ' . $storeIdsStr;
                if ($i < $numberOfDivisions - 1) {
                    $cmd .= ' & ';
                }
            }
            exec($cmd);
            $endTime = Carbon::now();
            Log::info('End: ' . $endTime->format('Y-m-d H:i:s'));
        } catch (Throwable $e) {
            Log::error($e);
        }
    }
}

上記の例だと、店舗を10分割した上で、artisan コマンドのオプションとしてそれぞれのコマンドが担当する店舗を割り当てています。

これで処理時間を大幅に削減することができ、一件落着……と思ったのですが……。

浮かび上がった問題

実際に上記のコードで店舗数を増やしながら実行していくと、あるタイミングから動作に異変が見られます。

1万店舗のとき

[2024-07-12 12:39:46] local.INFO: Start: 2024-07-12 12:39:46  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:49] local.INFO: 1000  
[2024-07-12 12:39:59] local.INFO: End: 2024-07-12 12:39:59

2万店舗のとき

[2024-07-12 12:35:23] local.INFO: Start: 2024-07-12 12:35:23
[2024-07-12 12:35:24] local.INFO: End: 2024-07-12 12:35:24

ご覧の通り、ログが出力されなくなりました。
ログが出力されないということは、当該箇所が実行されなかったということになりそうですが、その一方でエラーログが出力されている、というわけでもありません。

何らかの理由で実行されなかったにも関わらずエラーも発生しない、ということが起こり得るのか、ととても困惑しました。

exec()の仕様

困ったときに頼るものといえば、まずはドキュメントです。
execの説明として以下のように記載があります。

exec
(PHP 4, PHP 5, PHP 7, PHP 8)
exec — 外部プログラムを実行する

説明 ¶
exec(string $command, array &$output = null, int &$result_code = null): string|false

exec() は指定されたコマンド command を実行します。

パラメータ ¶
command
実行するコマンド

output
引数 output が存在する場合、指定した配列は、コマンドからの出力の各行で埋められます。 \n のような後に続く空白は、この配列には含まれません。配列に既に何らかの要素が含まれる場合は、exec() は配列の最後に追加されることに注意してください。関数が要素を追加することを望まないのなら、それが exec() に渡される前に、配列の unset() を呼び出してください。

result_code
引数result_codeが、引数 output と共に存在する場合、実行したコマンドのステータスがこの変数に書かれます。

戻り値 ¶
コマンド結果の最後の行を返します。コマンドを実行し、一切干渉を受けずに直接コマンドから全てのデータを受けとる必要があるならば、passthru() 関数を使ってください。

失敗時に false を返します。

実行されたコマンドの出力を取得するには、必ず output パラメータを設定・使用してください。

https://www.php.net/manual/ja/function.exec.php

気になったのはここの記述です。

result_code
引数result_codeが、引数 output と共に存在する場合、実行したコマンドのステータスがこの変数に書かれます。

https://www.php.net/manual/ja/function.exec.php

コマンドのステータスが変数に入るということは、当然実行したコマンドが何らかの理由で失敗した場合にもこの変数にステータスが入ることが想像できます。
それはつまり、exec関数そのものの成否は、指定したコマンドの成否には依存しないことを示しています。

前章で「（コマンドが）何らかの理由で実行されなかったにも関わらずエラーも発生しない」という事象が発生したのはどうやらこの仕様が原因だったようです。

そもそもの原因

何が起きたかを理解したところで、そもそもなぜコマンドを実行できなかったのでしょうか。
察しの良い方は既にお気づきかもしれませんが、原因はコマンドの長さにありました。

最初に例示したコードでは、コマンドのオプションとして-S (店舗ID)を店舗の数だけ付加する形になっています。これはつまり、店舗が増えれば増えるほどこの部分が長くなっていきます。
そして、コマンドの実行には長さの上限がありました。この上限はxargs -show-limitsを実行した際のSize of command buffer we are actually usingで確認できます。
この値は環境に依存するかと思いますが、検証時には下記のように131,072でした。

Size of command buffer we are actually using: 131072

上記の上限を基に、今回の例で上限を超過するタイミングを計算してみます。

php artisan app:output-stores
- 29 * 10
-S {id}
- {4 + (桁数)} * (店舗数)
&
- 3 * 9

上記で計算していくと、15,762店舗で131,069、15,763店舗で131,078となり上限を超過します。
そして、実際に試してみると…

15,762店舗

[2024-07-12 12:44:50] local.INFO: Start: 2024-07-12 12:44:50  
[2024-07-12 12:44:54] local.INFO: 1576  
[2024-07-12 12:44:54] local.INFO: 1576  
[2024-07-12 12:44:54] local.INFO: 1576  
[2024-07-12 12:44:54] local.INFO: 1576  
[2024-07-12 12:44:54] local.INFO: 1577  
[2024-07-12 12:44:55] local.INFO: 1576  
[2024-07-12 12:44:55] local.INFO: 1576  
[2024-07-12 12:44:55] local.INFO: 1576  
[2024-07-12 12:44:56] local.INFO: 1576  
[2024-07-12 12:44:56] local.INFO: 1577  
[2024-07-12 12:45:06] local.INFO: End: 2024-07-12 12:45:06

15,763店舗

[2024-07-12 12:45:32] local.INFO: Start: 2024-07-12 16:45:32  
[2024-07-12 12:45:33] local.INFO: End: 2024-07-12 16:45:33

見事上限値を境に動作が変化することを確認できました。
どうやらコマンドの長さ上限を超過してしまったため、正常に実行されず、ログも出力されなかった、ということで間違いなさそうです。

対策

今回の検証の結果、以下のことが分かりました。

コマンド実行時にはコマンドの長さに制限がある
長さ制限を超過した場合、exec関数自体はエラーにならないが呼び出すコマンドは正常に動作しない

この事象を避けるためには、コマンドの長さが何かに依存して増えていくような実装を避ける必要があります。
例えば、コマンドのオプションとして大量のIDを渡すのではなく、各バッチ処理の中でIDを動的に取得する等ですね。

また、実際の実装ではresult_code の値を確認する処理も入れることで、今回の事象以外の異常にも気づくことができるようにしています。

まとめ

今回は、店舗数の増加に伴うバッチ処理の処理時間増加への対策に関する取り組みを紹介させていただきました。
今回紹介した並行実行は、処理時間増加への対策の一部ではありますが、ご参考になれば幸いです。

最後に

カンリーでは、共に働く仲間を募集しています！
まずはカジュアル面談からでも問題ありませんので、興味のある方は是非お問い合わせください。

この記事が気に入ったらサポートをしてみませんか？