Tweet
Tweet

Slide 1

Slide 1 text

© LayerX Inc. Goのライブラリのバグを見つけてから直すまで 2024/05/24 layerx.go #0 Tomoaki Kitaoka Go MachineryでGraceful shutdownできてないバグを直した話

Slide 2

Slide 2 text

2 © LayerX Inc. 自己紹介 北岡 知晃（Tomoaki Kitaoka）@tapioca_pudd 2019年〜 株式会社LayerX バクラク事業部 機械学習チーム Software Engineer ● インターン→新卒入社 ● バクラクのリリース初期から AI-OCR機能の開発 ● Go歴3年くらい ● 趣味は体を鍛えること（クロスフィット）と服を作ること

Slide 3

Slide 3 text

目次 Agenda ● 背景 ● 起きていた事象 ● 調査する ● デバッグする ● 修正する ● さいごに

Slide 4

Slide 4 text

背景

Slide 5

Slide 5 text

© LayerX Inc. 5 ● 請求書に記入されている項目（支払期日や支払金 額、取引先名など）を目視で確認して、ミスなく入 力・管理することはとても負荷の高い仕事 ○ 枚数が増えるにつれてミスが起こりやすい ○ 帳票のフォーマットが多種に渡り単純に大変 ○ ミスは許されないためダブルチェック等確認 作業にもコストがかかってしまう バクラクのAI-OCR 背景

Slide 6

Slide 6 text

© LayerX Inc. 6 バクラク請求書 AI-OCR（請求書読み取り）機能のデモ 背景

Slide 7

Slide 7 text

© LayerX Inc. 7 バクラクのAI-OCRを支える非同期処理アーキテクチャ 背景 ファイルを扱う処理は重く、また突発的に大量のリクエストが来ることもあるため非同期処理のアーキテクチャを採用。 Lambda ECS 2. 重い処理は分離 （同期呼び出し） ECS SQS 3. 次の処理へ SQS 4.受信 S3 1. リクエスト SageMaker Lambda S3 SageMaker AI-OCRのAPIサーバーでは主にGo言語を採用しており、非同期で実行したい処理はメッセージキューとしてAmazon SQS、 メッセージの送受信やジョブワーカーの管理にはMachinery(v1)を使用しています。

Slide 8

Slide 8 text

© LayerX Inc. 8 MachineryはGo製の非同期タスク管理フレームワーク 背景 SQS ECS メッセージ 受信 非同期処理 SQS メッセージ送 信 ↑ ここで動くのが machinery ● メッセージブローカーとして、 SQSはもちろん、RedisやAMQPなども利用可能 ● メッセージに応じて異なるタスクを実行するだけでなく、遅延実行したり、エラーのリトライ時に はタイミングや回数の制御もでき、多段タスクや並列タスクの実行も可能 ● タスクの定期的な実行も可能 参考：https://github.com/RichardKnop/machinery

Slide 9

Slide 9 text

起きていた事象

Slide 10

Slide 10 text

© LayerX Inc. 10 デプロイ時になぜか毎回リクエストが数件タイムアウト 起きていた事象 ECS ECS 新ジョブワーカー 旧ジョブワーカー AI-OCRの非同期処理を担うジョブワーカーのデプロイ時、新しいジョブワーカーが起動して旧ジョブワーカー が停止する切り替えのタイミングで、毎度数件のリクエストがタイムアウトしていた。 c注：非同期で処理するようにはしているものの、client側に一定時間内にレスポンスを返したいのでタイムアウトを設定している部分がある

Slide 11

Slide 11 text

調査する

Slide 12

Slide 12 text

© LayerX Inc. 12 調査する ECS 旧ジョブワーカー 旧workerのログを見る terminateのシグナルを受信してから0.2秒ほどでGracefull shutdownしている ※Graceful Shutdown:現在処理中のリクエストを適切に完了させ、新しいリクエストを受け付けずにプロセスを終了させる こと

Slide 13

Slide 13 text

© LayerX Inc. 13 調査する タイムアウトしているリクエストを追う 旧ジョブワーカーで実行 新ジョブワーカーで再実行 SQSの可視性タイムアウトと 同じ時間経過後再実行 タイムアウトしているリクエストを追ってみると、Amazon SQSの可視性タイムアウトと同じ時間 経過後ジョブが再実行されている形跡を発見 ※可視性タイムアウト： メッセージが受信された直後は、メッセージはキューに保留されたままです。他のコンシューマーが同じメッセー ジを再び処理しないように、 Amazon SQSは可視性タイムアウト、つまり Amazon SQS が他のカスタマーがそのメッセージの受信や 処理できなくなる期間を設定します。デフォルトの可視性タイムアウトは 30秒です。 https://docs.aws.amazon.com/ja_jp/AWSSimpleQueueService/latest/SQSDeveloperGuide/sqs-visibility-timeout.html

Slide 14

Slide 14 text

© LayerX Inc. 14 調査する タイムアウトしているリクエストを追う 旧workerで実行 新workerで再実行 SQSの可視性タイムアウトと 同じ時間経過後再実行 タイムアウトしているリクエストを追ってみると、SQSの可視性タイムアウトと同じ時間経過後ジョ ブが再実行されている形跡を発見 🤔 SQSのメッセージが可視性タイムアウトになっ ている場合、メッセージの受信自体はされてい る。 となると旧ジョブワーカーがGraceful Shutdownできてないのでは？

Slide 15

Slide 15 text

© LayerX Inc. 15 調査する Machineryのコードを読む 具体的にシャットダウン処理が走っているところ

Slide 16

Slide 16 text

© LayerX Inc. 16 調査する Machineryのコードを読む(worker.Quit()の中身) ① consumeの停止 ② receiveの停止

Slide 17

Slide 17 text

© LayerX Inc. 17 調査する 仮説を立てる メッセージの受信中の間に terminateを受けると、先にメッセージを処理する goroutine（Consume）を終了させ てしまうため、受信中だったメッセージが受信完了しても処理できていないのではないか ?

Slide 18

Slide 18 text

© LayerX Inc. 18 調査する 仮説を立てる メッセージの受信中の間に terminateを受けると、先にメッセージを処理する goroutine（Consume）を終了させ てしまうため、受信中だったメッセージが受信完了しても処理できていないのではないか ? 厨房締め作業 完了 締め作業を終えた厨房に オーダーが入る 飲食店で例えると、厨房の締め作 業も終わったのに追加でオーダー が入ってきたイメージ

Slide 19

Slide 19 text

デバッグする

Slide 20

Slide 20 text

© LayerX Inc. 20 Machineryをcloneしローカルで動かす デバッグする go mod edit -replace で元々のライブラリへの参照を別のライブラリへ一発で切り替えできて便利

Slide 21

Slide 21 text

© LayerX Inc. 21 デバッグ用のログを仕込んでみる デバッグする 旧ジョブワーカー 新ジョブワーカー ①メッセージの受信を開始 ②受信したメッセージが処理されることなく gracefully shutdown ③新しいジョブワーカーでメッセージを受信 注：メッセージ受信中にterminateのsingalを受け取ることが重要なの で、receiveの処理にsleep処理を入れ、事象を再現しやすくした

Slide 22

Slide 22 text

© LayerX Inc. 22 時系列に並べてみる デバッグする 旧ジョブワーカー (worker1) 新ジョブワーカー (worker2)

Slide 23

Slide 23 text

© LayerX Inc. 23 時系列に並べてみる デバッグする 旧ジョブワーカー (worker1) 新ジョブワーカー (worker2) 😃 仮説は合っていそうだ！！！

Slide 24

Slide 24 text

修正する

Slide 25

Slide 25 text

© LayerX Inc. 25 修正する StopConsuming()でConsumeを止めた後に、Receiveを止めているのが問題なので、Receiveを先に止め、 Receive中の処理が完全に消化されたらConsumeも止めてあげるようにします receiveを完全に終了させてからconsumeも止める

Slide 26

Slide 26 text

© LayerX Inc. 26 修正する StopConsuming()でConsumeを止めた後に、Receiveを止めているのが問題なので、Receiveを先に止め、 Receive中の処理が完全に消化されたらConsumeも止めてあげるようにします receiveを完全に終了させてからconsumeも止める ラストオーダー 全部聞き終える 厨房締め作業 完了

Slide 27

Slide 27 text

© LayerX Inc. 27 修正する 修正する https://github.com/tomo25/machinery/pull/1/files

Slide 28

Slide 28 text

さいごに

Slide 29

Slide 29 text

© LayerX Inc. 29 さいごに 結果と感想 ● 修正後、デプロイに伴うジョブワーカーのタイムアウトエラーは0件に。🎉🎉🎉 ● プロダクトローンチ直後はジョブワーカーの切り替えタイミングにピンポイントでリクエストがくることがなく気がつか なったが、プロダクトの規模が徐々に大きくなるにつれ発覚。リリースのタイミングは常に不審なログがないか注視すべ し。 ● ローカル環境ではlocalstackを利用することでSQS+Machineryの構成を再現できて便利だった。 ● go mod edit -replace 初めて使ったけどコマンド一発で参照するライブラリの変更が完結して便利だった。

Slide 30

Slide 30 text

© LayerX Inc. 30 さいごに バクラクではMLOpsエンジニアを大大大募集しています！ バクラクのMLOpsについて書いたブログ カジュアル面談 サマーインターンも大募集中！ ソフトウェアエンジニア 機械学習エンジニア