LoginSignup
34
19

More than 5 years have passed since last update.

LaravelAdvent Calendar 2018Day 2
@sh-ogawa(ogawa)inバイザー株式会社

SQSキューワーカーがメモリリークする件について

Last updated at Posted at 2018-12-02

この記事について

Laravel Advent Calendar 2018 - Qiita の 2日目 の記事です。

Laravelの標準機能に搭載されているSQSキューワーカーがメモリリークする件について、わかっていることをシェアします。

また、問題解決するのが苦手だという方には、考え方みたいなのは参考になるかもしれません。

手順を書いていくので、結果だけ知りたい人は、一番下のまとめを見ていただければ〜。

メモリリークがわかるまで

それはサーバーリソースのモニタリングから発覚した

それは弊社インフラエンジニアの@s-sasaki からとあるEC2の利用メモリが時間経過とともに増え続けているという一報から始まりました。

そのサーバーとはSQSキューワーカーで処理されるアプリケーションが載っているだけのサーバーだったので、ここから原因究明が始まる。

とはいえ、この時点では私はそんな問題があるんだ〜と、とりあえず気になりつつも傍観してますが。

とりあえずググってみる

「sqs worker memory leak」とかでググるとgithubのissueが出てくるけど、restartせよって書いてあるだけで、仕様であるようなことが書かれていることがわかります。

というのが一旦報告されてそんなバカなことはないだろうということで、原因究明していくことになります。

みんな原因がわからない問題を解くの面白そうじゃん？ってことで私も取り組んでみることにしました。

問題の切り分け

そもそも以下の２点のうちどちらに問題があるのか切り分けないといけないです。

  • 自分たちのアプリケーションが悪いのか
  • Laravelのキューワーカーが悪いのか

これは試験用環境ということで、自分たちのアプケーションは動いていないということは分かっているので、
自分たちのアプリケーションは除外できます。

この時点でLaravelのキューワーカーが悪いっぽい、ということに絞って調べていくことになります。

キューワーカーのどれに問題があるのかを探る

キューワーカーと一言で言っても、Laravelには以下を利用するケースのものが存在します。

  • database
  • redis
  • sqs

SQSキューワーカーに問題があることは分かっていますが、
どのワーカーでもこの問題どれでも起きることなのかどうかは知っておいた方が良いので、知っておきます。

本来は検証コードを書いて検証するところですが、たまたまdatabaseキューでも動いているサーバーがあったので、
そちらのモニタリング結果を見ることで切り分けはできました。

databaseキューでは発生していないことはわかるので、sqsキューワーカーだけの問題であることがわかります。

SQSキューワーカーに絞って原因を探る

いちいちAmazon SQSに繋ぐのはめんどくさいので、LocalStackを使って検証します。

LocalStackとLaravelでの使い方については、以下に社内勉強会で使った資料があるので参照していただければ〜。

手元のIDEはIntelliJなので、Evaluate logで利用メモリをログに吐くようにして確認します。
仕掛ける場所は

Illuminate\Queue\Worker::daemon()

php artisan queue:workを叩けば、メモリが増えていくことがわかります。
※検証した時のログは既に手に入らなかった・・・

この時点でHttpリクエストすると何か溜まるということが分かったので、次は以下を調べてみます。

  • GuzzleHttpが悪いのか
  • AWS SDK PHPのコードが悪いのか

SQSワーカーが使用しているaws-sdk-phpのSqsClientは中身はGuzzleHttpの非同期リクエストを使用しているので、

GuzzleHttpが根本的に悪いのか、aws-sdk-phpのGuzzleHttpの使い方が悪いのかを切り分けします。

そもそもですが、PHPみたいなシングルプロセスで動く機能において、常駐処理させるということが異質と言わざるを負えなく、誰も結果を知らないので自分でやります。

Guzzleで非同期処理

実際にSqsClientで使用しいているrequestAsyncを無限ループで使用するコードを書いて検証します。


use GuzzleHttp\Client;

class Hoge
{
    public exec()
    {
        $client = new Client();

        while (true) {
            //$client = new Client();
            $promise = $client->requestAsync('GET', 'http://hogehoge/');
            $promise->then(
                function ($res) {
                    logger()->debug('>>>>>>>>>>> ', compact('res'));
                },
                function ($e) {
                    logger()->debug('>>>>>>>>>>> ', compact('e'));
                }
            )->otherwise(
                function ($res) {
                    logger()->debug('>>>>>>>>>>> ', compact('res'));
                }
            );

            $responses = \GuzzleHttp\Promise\promise_for($promise)->wait();

            logger()->debug('>>>>>>>>>>>>>>>>>> ' . memory_get_usage());
        }
    }
}

このコードを実行すると、特にメモリの継続的な増加が見られないことが判ります。

これで、ほぼほぼaws-sdk-phpのGuzzleHttpの使い方が悪いというのが確定。
個人的には非同期リクエストを投げまくっても正しく書かれていればメモリリークはしない、ということも分かったので、これ自体の検証も今後には役立ちます。

aws-sdk-phpでSQSに要求を投げる

以下のコードはLocalStackに要求を投げるコードになります。

use Aws\Sqs\SqsClient;
class Hoge
{
    public exec()
    {
        $client = new SqsClient([
            'profile' => 'default',
            'region' => 'ap-northeast-1',
            'version' => '2012-11-05'
         ]);

        while (true) {

            $receiveMessage = $client->receiveMessage([
                'AttributeNames' => ['SentTimestamp'],
                'MaxNumberOfMessages' => 1,
                'MessageAttributeNames' => ['All'],
                'QueueUrl' => 'http://192.168.20.31:4576/queue/test', // REQUIRED
                'Endpoint' => 'http://192.168.20.31:4576',
                'WaitTimeSeconds' => 0,
            ]);

            echo memory_get_usage();
        }
    }
}

このコードを実行するとリクエストの度に使用メモリが増え続けていくことが確認できます。

ここから先は追おうとしてもネイティブが絡んでくるのでよく分からないため、aws-sdk-phpのリポジトリにissueを上げました。

aws-sdkにしても、そもそも無限ループで使われることなんて想定はしていないでしょうから、あくまでもこちらの使い方が悪いですよねーって程でお伺いしたところ、

以前にも似たような質問があって、その時は「gc_collect_cycles」を呼んで回避できた、という回答が得られたので、試して見ることに。

Illuminate\Queue\Worker::daemon()

にEvalueate and Logでgc_collect_cyclesを仕込んで

php artisan queue:workすると、


2018-11-06 09:37:15.807606      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 18159744           {"line":null}
2018-11-06 09:37:19.130764      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 20974928           {"line":null}
2018-11-06 09:37:22.160927      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 20974928           {"line":null}
2018-11-06 09:37:25.182886      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 20974928           {"line":null}
2018-11-06 09:37:28.206444      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 20974928           {"line":null}
2018-11-06 09:37:31.230250      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 20974928           {"line":null}
2018-11-06 09:37:34.259795      local.INFO      local.test     5780    8d535d9 >>>>>>>>>>>>>>>>>>>> 20974928           {"line":null}

上記の通り見事に増えなくなりました。
※>>>>>>>>>>>>>>>>>>>>の後ろが使用メモリ

これを以って、laravel/ideaにissueを上げて、現在どこに入れるか？でやりとりさせてもらっていましたが、
助け舟もあって、maxメモリを超えた時に一回gc_collect_cyclesを呼ぶ方向でパッチを当ててもらえそうです。
（ので、全ワーカー共通のところに入れてもらえそう）

改善は待ってればされそうだけど、それまでは？

待ってれば問題は解決されそうですが、どこで入るかはまだ分からないので、
何かできることはないか？ということで何かできることがないかを探ります。

Cloud Watchをみているとやたらとempty receive dataが多いということに気がつきました。

私の感覚だとMessaging Queueってメッセージをレシーブするまで限界まで待つモノじゃないの？という感覚がある（昔Linuxのリモートメッセージ機能を使って、確かにそういう実装をC言語でした）ので、

SQSでそういうことできないの？っていうのを公式ドキュメント読んで調べたら、

ロングポーリングの設定が存在しているので、これ使えばコード触らずに延命はできていいじゃんってことで、入れるようにお願いして入れてもらいました。
（夜中に１回再起動するとかなら全然問題ないので。そもそもメッセージの受信保証はできているのにそんなリアルタイム性いるのか？っていうのは個人的には思ってるけど）空メッセージ受信でも、メッセージの有無を問い合わせれば１リクエストにカウントされるので、これはこれで意味があります。

2018/12/27追加

暫定対応として@sisveさんから以下の暫定対応が提案されました。

class AppServiceProvider extends ServiceProvider
{
    /**
     * Bootstrap any application services.
     *
     * @return void
     */
    public function boot()
    {
        Queue::looping(function() {
            gc_collect_cycles();
        });
    }
}

氏のコメントも一緒に載せておきます。

You're probably thinking of the JobProcessing/JobProcessed/JobFailed events which is tied to a specific job and wouldn't execute on an empty queue.

The Looping event is fired every time the worker checks for an available job (and either executes it, or sleep if there was no available job). I use dedicated listener classes for my logic, but you can just throw this into your favorite service provider to execute gc_collect_cycles() between every job. It's probably not appropriate to use on a framework level, but you can probably use it as a workaround in your code base until Laravel has better fix.

ジョブの有無をチェックする前に毎回コールされるので、すべてのキューワーカーで実行されるのが微妙ですが、
一旦これで十分なので使っておこうと思います。

まとめ

SQSキューワーカーがメモリリークする件については、

  • 現状は避けようがない(vender配下をいぢればまぁ。。それかforkして自分でパッチ当ててpackagistで公開して使う)
  • 待ってれば解消される可能性は高い
  • SQSの設定にロングポーリングを入れることで症状の軽減はできる

あとやっぱり個人的には、いくらフレームワークが標準でAWSの機能を使えるようにしているからって、
そのAWSの機能のことをたいして知らない状態で使うべきではないと思ったのでした。
公式ドキュメントは一周しましょう。

おわりに

Laravel アドベントカレンダー2日目は皆さんもなんだこれ？って思われていそうなSQSキューワーカーがメモリリークする件をお届けしました。

明日は @bumptakayuki さんが沖縄から何かをお届けしてくれると思います！

34
19
5

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
34
19