Cloud Run のログを標準出力に出したらメモリが劇的に節約されてパフォーマンスも良くなった話
テストで満点を取れるようになって、足が速くなって、恋人ができて、インスタンスの安定性も改善されました！！！
こんにちは、ダイニーの whatasoda です。ダイニーでは4年以上 Cloud Run を使っていますが、ロギングには @google-cloud/logging-winston を利用しています。これまで Cloud Logging API を直接呼び出す方式で利用してきて特段不便を感じることはありませんでしたが、最近これを Cloud Run の標準出力に書き込む方式へと変更したところタイトルのような効果を得ることが出来ました。（そもそも Cloud Run では標準出力に書き込まれたテキストを自動的に Cloud Logging に記録してくれるようになっています。）
なお、ダイニーでは NestJS アプリケーションを Node.js で実行しているため、この記事は Cloud Run で Node.js を利用している方を主な対象として想定しています。
何をして、どんな変化を得られたのか
@google-cloud/logging-winston を利用する際は winston の createLogger の transports のアイテムとして LoggingWinston のインスタンスを渡すことになります。以前はデフォルト設定、つまりは Cloud Logging API を直接呼び出す設定を利用していましたが、今回の変更で標準出力に書き込む設定を使うようになりました。
標準出力に書き込むようにするために必要なのはredirectToStdout と useMessageField というオプションです。これらのオプションの詳しい説明は公式のドキュメントを参照してください。細かい部分は実際のコードと異なりますがそれぞれ以下のように設定します。
import { LoggingWinston } from "@google-cloud/logging-winston";
import { createLogger } from "winston";
const logger = createLogger({
transports: [
new LoggingWinston({
// これにより Cloud Logging API ではなく標準出力にログを記録するようになる
redirectToStdout: true,
// デフォルト値は true で logger に与えられたデータをオブジェクトでラップして書き込む
// 例: { "message": { /* log data */ } }
// false にするとログデータをそのまま標準出力に書き込んでくれるようになる
useMessageField: false,
}),
],
});
この変更をリリースしてからインフラメトリクスが以下のように変化しました。画像中央の青い線が該当の変更を適用したタイミングを示しています。
ダイニーのサービスにはランチ帯とディナー帯のピークが存在します。ランチ帯のピークはディナー帯のピークと比べると小さめではありますが、ディナー帯はインスタンス数がスケールすることで対処するようになっているため、インスタンス一つあたりにかかる負荷としてはランチ帯でもディナー帯と大きな乖離はありません。
今回の変更はランチ帯のピークよりも前に適用したのですが、当日のランチ帯のピークからメモリ使用率・ CPU 使用率共に大きな改善が見られます。コンテナインスタンス時間もわずかではありますが減少傾向にあります。なお、当時の Cloud Run のスペックは 1 vCPU & 4 GiB RAM でした。
本記事の公開日現在も CPU・メモリ共に割り当てや同時実行数の調整をしてインフラコストの最適化を進めています。画像で示した期間では7日間ほどスペックを据え置きしていますが、これは週末に訪れる飲食店利用のピークでも問題なく稼働できることを確認するためにあえて据え置きしています。
グラフの左側、変更を適用する前のメトリクスを見てみるとメモリ使用率・ CPU 使用率共に毎日 100％ に張り付いているインスタンスがあることがわかると思います。この状況自体は問題視していたものの、特段そこに関連付けることができる実影響をあまり観測できておらず優先度を上げきれずにいました。そんな中、メモリ使用率が 100％ に張り付いていることが関連したとある事象を発見したことでログの出力先を変更するに至りました。
ログが3時間以上遅延して記録されていた
ダイニーでは様々な指標を用いてアラートを設定しており、その中には特定の条件にヒットするログを検知して発動するものも存在しています。ある日、とあるアラートが鳴ったため調査をしたところ 3時間以上前のログがアラートのトリガーとなっていました。そのログをよく見てみると timestamp （ログのオブジェクトが発行された時間）は3時間以上前でしたが receiveTimestamp （ログが Cloud Logging API に受け取られた時間）はアラートが発動したタイミングとほぼ同じ時間でした。
その日ログが大幅に遅延していたのは特定のインスタンスのみで、そのインスタンスではリクエストを受け付けることが出来ずに The request has been terminated because it has reached the maximum request timeout. で始まるエラーが発生していました。
アラートが鳴ったタイミングでは既にその事象は解消されており、通常通りリクエストを捌くことができているようでした。しかし、アプリケーションログは滞留していてその時点ではまだ最新のログを観測出来ませんでした。徐々に送信されてはいたため様子を見ていたのですが、滞留されたログが解消されて最新のログをニアリアルタイムに確認できる状態になるまで 40 分ほどの時間を要しました。
このことから、以下のことが起きていると推測しました。
当時のロギングの構成ではログが直ちは送信されず、滞留することがある
滞留しているログのデータはメモリ上に蓄積されていく
リクエストの内容を保持するためのメモリ領域の確保すらできない状況になった
この問題はアプリケーションの安定性やパフォーマンスだけではなく、監視性にも影響を与える可能性があります。ログの遅延もそうなのですが、ログが滞留しているときに何らかの原因でインスタンスが終了してしまうとメモリ上のログが揮発してしまい、そのログは永遠に失われてしまうことになるからです。これらの問題はログを標準出力に出すようにしてからは解消されています。
ダイニーでは現在標準出力に出す方法を採用していますが、この問題を解決し得る他の方法も存在しています。今回の記事ではあまり深くは触れませんが、検討した方法をいくつかご紹介します。
ログをなるべく早くアプリケーションの外に出力したい
まず、達成するべきことはログをなるべく早くアプリケーションの外に出して、メモリを開放してあげるということでした。検討したオプションについて箇条書きでまとめておきます。
ログを標準出力に記録する
Node.js の IO の仕組み的にパフォーマンスが一番良さそう？
logName が固定になってしまう
Cloud Logging API を呼び出す頻度などを調整する
滞留しないペースで送信してあげれば良いかも？
仮にペースよく送信できたとしても API 呼び出しが発生するため一定のオーバーヘッドは存在する
sidecar あるいは Compute Engine で Logging エージェントまたは Ops エージェントのプロセスを立ち上げ、そこにログを送る
Cloud Logging API を叩く役割を分けることができれば解決するかも？
Logging エージェントは利用可能だが開発は終了しており、 Ops エージェントはどちらかというと Compute Engine 向けの実装
ダイニーでは一部のログを BigQuery にエクスポートしているのですが、その際 BigQuery 側で作成されるテーブル名は logName を元に決定され、変更することが出来ません。また、ログベースの指標などでも logName を使ったログクエリを使用しているものがありました。そのため標準出力に記録するように変更するとそれらにも対処する必要があるのですが、総合的な対応コストやパフォーマンスなどを考慮した結果、まずは今回の変更を試してみることになり、劇的な効果を得ることが出来ました。
構造化ログへの対応 & ダイニーが気をつけていること
最後に、Google Cloud の 構造化ログについて少し触れます。 Cloud Run で標準出力に記録する場合でも構造化ログは利用することが出来ますが、少しだけ注意が必要な部分があります。ついでにダイニーがログを記録する際に気をつけていることもご紹介します。
labels に null などの値を含めない
本来、 labels に指定した値はログのトップレベルの labels というフィールド内に格納されることを期待しているかと思いますが、標準出力に記録する場合は labels の中に一つでも null が含まれていると以下のように jsonPayload 内の logging.googleapis.com/labels というフィールド内に格納されてしまいます
この事象への対策としてダイニーでは全てを string に直してから logger を呼び出すようにしています
timestamp は必ず Date オブジェクトで渡す
ログが発行された正確な時間を記録するために重要です
LogginWinston の実装上 Date オブジェクトになっていないと logger を呼び出した時間ではなく logger がそのログを処理するときの時間に上書きされてしまいます
trace を設定する
リクエスト毎でログをフィルターできるようになります。
ダイニーでは X-Cloud-Trace-Context から得られる値を設定しています（参考： https://cloud.google.com/trace/docs/trace-context ）
labels.instanceId は自動で入るので便利
便利！
We’re hiring!
ダイニーの Platform Team では飲食業界に確実に価値提供をし続けられるようにする取り組みを日々行っており、一緒に働いてくれる仲間を募集しています。興味がある方はぜひ以下のリンクをチェックしてみてください。