Zenn
📈

Cloud Functionsでメモリ不足になった話

2021/11/21に公開
Golang
GCP
#
gcf
tech

株式会社var CTOのSleekです。

本日は、GCPのCloud Functionsの中のとある関数でメモリ不足になったことについて書きます。

概要

  • GCPのアラートでCloud Functionsでメモリ不足で関数が落ちたことが通知される
  • 調査すると時間が経つにつれメモリ使用量が増大していくことが確認できた
  • 原因はFirestoreなどをサービスを利用するためのclientをCloseしていなかったからであった

Google Cloud Functionsについて

Google Cloud Functions(GCF)はGCPが提供するサーバレス・FaaS(Function-as-a-Service)であるサービスです。

利用者はHTTPやPub/Subからリクエストを受け付けてデプロイした関数を実行することができます。

サーバレスのサービスであるため、サーバ管理やスケーリングについて気にする必要がなく、また従量課金制であるため安価に利用することができます。

作成したGCFについて

今回作成していたGCFは以下のようなものです。

  • Go言語で書かれており、Pub/Subをイベントトリガーとして設定している
  • Pub/SubにはCloud Schedulerを利用して1分毎にメッセージが送られるようになっており、その度にGCFが実行される
  • GCFはFirestoreからデータを取得し、条件を満たすと別のPub/Subイベントにメッセージを送る

今回の発端

弊社が提供しているEnvader（エンベーダー）というサービスでは、GCP内でエラーが発生するとSlackのチャンネルで通知がされるように構成されています。サービス提供が始まって1ヶ月半ほど経ち、誤検知やバグの修正もあらかた終わりアラートがほぼ無くなってきたタイミングで以下の画像のような通知が来ました。

log.png

function_name= のところに関数名が出ているのですが、この関数で発生したアラートは初めてでした。

原因調査

GCPのLoggingというサービスでログを確認すると以下のようにメモリ使用量の限度に達し関数が中断されたとのことです。

log2.png

このGCFが行うことから考えるとFirestoreに保存されているデータが異常に増えない限りはメモリ使用量が増えることはないと思っていた上、Firestore内のデータはかなり小さいため、この現象はとても不自然でした。

GCFはデフォルトで実行時間やメモリ使用率など様々なメトリクスが記録されているため、ダッシュボードで確認すると以下のようなグラフになっていました。

metrics.png

縦に入っている青い線がアラートが発生したタイミングです。徐々にメモリ使用量が限界値に向かって上昇していき、限界値に達すると一気にリセットされていることが分かります。しかし、Firestoreのデータは時間によって蓄積されていくようなものではないため、このGCF自体に何かしら問題があるということがわかりました。

原因の特定

この事象に出会うまでは、GCFでPub/Subトリガーを利用している場合、関数は毎回0から実行されており、関数が終了するとプログラム自体も終了するものだと思い込んでいました。しかし、この事象から考えるとメモリ上に何かしらのデータが蓄積されていったものだと考えるのが自然ため、デプロイした関数は常時待機状態で起動し続けており、基本的にはプログラムは終了しないという構成になっていると気づきました。

そうなると考えられるのは何かしらのメモリを解放し損なっているということです。ただの文字列や数字の変数であれば関数を抜けた時点でメモリを解放してくれるはずです。したがって作成したプログラムの中で一番怪しいところはfirestoreのclientを作成しているところだと当たりをつけました。

	client, err := firestore.NewClient(ctx, projectID)
	if err != nil {
		return err
	}
	iter := client.Collection(USERS).Documents(ctx)
	iters, err := iter.GetAll()
	if err != nil {
		return err
	}

パッと見て気付く方も多いとは思いますが、上記のコードではclientがCloseされていません。Firestoreでは新しいclientを作成したタイミングでgRPCによるコネクションプールを作成し、Closeしたタイミングでこのコネクションプールを解放します。

したがって通常の変数とは違って関数を抜けたタイミングで自動的にメモリが解放されることはなく、明示的にCloseをするかプログラム自体が終了するかでメモリが解放されます。ローカルでテストをしていたときは毎回プログラムが終了するようになっていたため、当然このことに気付く余地はありませんでした。

解決

単純にCloseするコードを追記しました。

	client, err := firestore.NewClient(ctx, projectID)
	if err != nil {
		return err
	}
	defer client.Close()
	iter := client.Collection(USERS).Documents(ctx)
	iters, err := iter.GetAll()
	if err != nil {
		return err
	}

先程と同じ画像ではありますが、上記の変更を行った16:30あたり以降はメモリ使用量が安定しています。

metrics.png

まとめ

  • CloseするべきものはちゃんとCloseをする
  • 関数を抜けたときに解放されないものもあるとこを忘れない
  • Logging・Monitoring・Notificationを簡単にやってくれるGCPは凄い

宣伝

弊社では、インフラ学習サイトEnvader（エンベーダー）を運営しています。オンライン上でLinuxやDatabaseの学習を簡単に行えるので是非使ってみてください。

https://envader.plus

GitHubで編集を提案

Discussion