12月も終盤、2019年も終盤、令和元年も終盤です。みなさんいかがお過ごしですか。ソーシャルゲーム事業部ゲーム技研の谷脇です。
この記事はTech KAYAC Advent Calendar 2019の24日目の記事です。
Migration Trackの方で結構書いたので、こっちは何書こうかなーとなったんですが、あえて小ネタでAWS Lambda使う時のTipsな感じで行きます。
AWS Lambdaのデバッグがしんどい件
僕はサーバレス・コンテナ以前からWebのサーバ開発をやっている人間なもので、動いているやつをダイレクトにソースコードいじってバグを直した経験があります。そこまで野蛮な方法を取らなくても、sshで入ってリクエスト叩きながらログを読んだり、プリントデバッグを仕込むなどの手段を使って、とにかくなんとか直す手段を持っていました。
しかし、コンテナでsshを封じられ、サーバレス環境ではさらに古来からのデバッグ手段を縛られる始末。
例えば、本番で特定のパラメータを入れたときだけ発生するバグは、あらかじめログを詳細に残しておかないと再現することすらままなりません。あと、サーバレスでお手軽にリクエスト単位で見れるログをどうやって吐くの？って問題もありますね。というのをAWS X-Rayを使って解決してみました。
新マスタデータ管理システムakashic
LambdaとX-Rayを組み合わせてみたのは、ゲームを作るための内製システムakashicです。
Lambda上のakashicのアプリケーションの特性としては、
- Go言語のLambda関数をALBでInvokeしている
- 1時間あたりのAPIリクエストが50回から100回程度。使われるのも営業時間中の4時間程度
- 1回の関数あたりの実行時間は10秒〜60秒
- Google Sheets APIの待ち時間が多くを占める
- Lambdaが起動するAPIは、Google Sheetsのメニューに埋め込んだGoogle App Scriptか、
akashic-clientというCLIコマンドから呼び出される
と言った感じです。業務に必要な内製ツールではよくあるようなワークロードではないでしょうか。
内製ツールの運用負荷というのを下げるという意味でも、akashicをAWS Lambdaで動かしています。複数人が同時に使っているときなどには、勝手にスケールアウトしますし、永続化層をakashicが持っていないため、Lambdaに適したアプリケーションであると言えます。
実際にこの構成で大体のケースではちゃんと動くのですが、スプレッドシートという自由な入力データを扱い特性から、使用している方からしばしば意図通りに動かないという問い合わせがありました。
よく多い、ちゃんと動かないという問い合わせとしては、
- APIの実行時間がタイムアウトしたという表示(GAS)
- 特定のシートを読み込んだときだけエラーが出る
などがあります。一個ずつ見ていきます。
「APIの実行時間がタイムアウトした」
akashicのGoogle Sheets統合の仕組みは、シート上のメニューからGoogle App Scriptの関数を実行し、関数の中でシートのキー名や各種オプションを読み取った上で、ALBにぶら下がっているLambdaにリクエストを投げているという仕組みです。
最初の方では別に問題がなかったのですが、開発が進んで取り込むマスタデータの量が多くなってきたところで、が「APIがタイムアウトしました」というエラーがGASのほうで出てきたようです。
早速Lambdaの実行時間を、ログを見て調べてみました。すると、リクエストを受けてからレスポンスを返しきるまで61秒から59秒ほどかかっていましたが、Lambda上では元気に200を返した気になっているログが出ています。
ここで、「はは〜ん、GAS側に1分でなにかが起こる制限があるんだな〜」と思って、GASのドキュメントを調べてみます。
GASユーザはよくご存知の通り、GASの実行時間には6分という制限があります。
Script runtime 6 min / execution
ですが、URL Fetchの項目を見てもリクエストやレスポンスのサイズに関する制限があるだけで、「1分的なもの」はありません。
うーむ、と思いましたが、とりあえず余裕を見て50秒ぐらいに納めればだいたいタイム・アウトしなくなるのはわかってたので高速化していきます。
「推測するな、計測せよ」
見出しの言葉の通り、何が時間を食っているのか（いや、推測はできていたのですが）知らないふりをして、計測する手段を導入します。
Lambdaで時間がかかるといえば何個かパターンがあります。
- VPC Lambdaによるコールドスタート問題
- この改善を入れた直後にこの問題は解消されています [発表] Lambda 関数が VPC 環境で改善されます | Amazon Web Services ブログ
- 単純にCPUを食っている
- 外部APIへのリクエストに時間がかかる
- AuroraやElastiCacheを使う場合はそれも含まれますが、akashicは使っていません
これを可視化するために使ったのが、分散トレーシングサービスのAWS X-Rayです。本来は、多数のマイクロサービスを束ねたようなサービスを一気通貫でログを見たり、リクエストの経路を追いかける目的のサービスですが、外部APIを多く叩くような場合でも有用です。
幸いなことにAWS LambdaはX-Rayとネイティブに連携出来るため、ECSなどで使うときのような別途デーモンを立てたりするような手間ありません。
https://docs.aws.amazon.com/ja_jp/lambda/latest/dg/lambda-x-ray.html
また、Goなので、X-Ray SDK for Goを使えば、だいたい事足ります......。いやそんな簡単なものではなかった。
Webサービスならまだしも、多くのフィルタやアウトプットする君を入れ替えられるakashicの設計では、一部のコンポーネントにうまくcontextが伝搬していないケースがありました。なので、そこそこの書き換えが発生しました。
別のサービスで、同じようなことを倍ぐらいやった、同僚のれもんさんの資料があるので、これを見てください。
開発期間数年のサービスの完成間際にcontext対応をぶち込む / introduce context.Context into long term project - Speaker Deck
なにはともあれ、akashicにX-Rayを導入できました。すると、このような感じでいい感じに...
oh...。やはりGoogle Sheets APIのレスポンス待ちで時間がかかっているようです。Google Sheets APIはデカいシートを一気にAPIで取ってこようとすると、Google側でタイムアウトしたり、何分も時間が掛かるケースがあったため、このように1つのファイルでも複数回にAPIリクエストを分割して取ってくる仕組みになっています。
どうやらここを並列化すれば良さそうですね。goroutineとchannelでちょちょちょいっと。
このとおりきれいに並列リクエスト化できましたね。ただ、API Quotaなどでn分間あたりのリクエスト数が決まっているので無闇矢鱈に並列化するのはやめましょう。ちなみに、Sheets API v4の場合は、1プロジェクトあたり100秒間で500リクエスト、1ユーザあたり100秒間で100リクエストという制限があります。注意しましょう。
Usage Limits | Sheets API | Google Developers
これで50秒以内にだいたい処理が終わるようになったため、タイムアウトが発生することはなくなりました。しかし、並列リクエストなどのチューニングを駆使しても1分を超えることはあるかと思います。そのときはStep FunctionsでLambdaを起動する形に改めようかと思っています。
「特定のシートを読み込んだときだけエラーが出る」
上記の話を見て、だいたいバグだったり入力側でどうにか出来る話が多いのですが、ここで困るのは再現手順です。そこで、以下のようにX-RayのAnnotationとして、リクエスト時のパラメータを埋め込んでみました。
xray.AddAnnotation(ctx, "SchemaRef", exportReq.SchemaRef) xray.AddAnnotation(ctx, "Tag", exportReq.Tag)
するとこのような感じでリクエストごとのパラメータが、トレース結果内に埋め込まれます。
また、お問い合わせIDとして、X-Rayのtrace_idを表示すると、エラーが出たといわれたときに「お問い合わせIDはなんですか」と聞くだけで、どういう状況でエラーが起こったかがわかります。
エラーログもtrace_idに紐付いているので、わざわざ同じ状況を確認しなくても、ログからエラー内容を確認することも出来るようになりました。
X-Rayのデメリット
カヤックでは内製システム以外でも、ユーザにレスポンスを返している部分でX-Rayを組み込んでいます。ですが、全てのリクエストに対してログをサンプリングしていると、お金がかかってしまいます。
なので、一般的には5%や1%程度のリクエストをサンプリングしてトレース記録を行ったり、例外が起こったときのみトレースログを送信するなどの工夫をしています。
ですが、内製システムのような場合ですとリクエスト数もたかが知れているので、全件トレースされてもそこまで料金に影響がありません。実質便利になるだけです。
もう一つのデメリットとして、ローカルで動かす際に、X-Rayデーモンがいないと言われて、エラーログが大量に出る場合があります。それに関しては、以下のようなemitterを噛まして、出力を抑制しています。
ss, _ := sampling.NewLocalizedStrategyFromJSONBytes(
[]byte(`{ "version": 2, "default": { "rate": 0 } }`),
)
xray.Configure(xray.Config{
SamplingStrategy: ss,
ContextMissingStrategy: ctxmissing.NewDefaultLogErrorStrategy(),
LogLevel: "error",
Emitter: &DiscardEmitter{},
})
// DiscardEmitter は どこにもログを送信しないemitterです type DiscardEmitter struct{} // Emit は本来XRayデーモンに送るメソッドですが何もしません func (d *DiscardEmitter) Emit(seg *xray.Segment) {} // RefreshEmitterWithAddress は本来XRayデーモンのアドレスを設定しますが何もしません func (d *DiscardEmitter) RefreshEmitterWithAddress(raddr *net.UDPAddr) {}
まとめ
- Lambdaでサーバレスアプリケーションを作る時に、デバッグやトラブルシューティング目的でX-Ray組み込むと便利という話をしました
- SAM Localを使ってデバッグするという別の方向性もあるかとは思います
- ですが、Google Sheets APIと組み合わせて使用する以上、実際にデータ出ないと出ない不具合を解決するためにX-Rayが便利でした
- 内製ツールをLambdaで作っておくと、ほぼ手放し運用ができますし、コストもかからないのでぴったりなユースケースです
