More than 3 years have passed since last update.

ActiveStorageをクラウドストレージ(GCS,S3, etc)で使ってた時に処理が遅くなる問題

Posted at 2020-07-24

概要

Heroku上で動かしていたRailsアプリの処理が遅かった時の調査メモです。
結論として、画像保存に使用していたGCPのクラウドストレージの部分がボトルネックとなっていました。

Herokuの無料プランでRailsを使った趣味のWEBサイトを構築運用しています。
当初から処理はあまり早くないものの、SQLに関してもRedisでキャッシュを入れたりしていたので、まぁ無料ならこんなものかと思っていました。

しかしながら、一部のページのみ他のページより早い事に気がつき、何が原因かを調べることとしました。

一般的な方法ですが、下記のコマンドでログを出力させて処理時間を調べる事にしました。

heroku logs --tail

デフォルトでRailsはDEBUGログで処理時間を色々出してくれるので、まずはそこを確認する事にしました。

当初はキャッシュしていない部分のSQLが遅いのかと思っていましたが、
SQLに関してはキャッシュも効いて遅いクエリも見つかりませんでした。

しかしながら、代わりに下記のような処理時間に100ms以上かかっているログが何箇所が見受けられました。

 GCS Storage (169.9ms) Checked if file exists at key: variants/xxxx

該当のサイトは画像をGCSにアップロードしており、その部分が関連している事が推測できました。
また、variantといったキーワードからActiveStorageの該当機能が影響していることもわかります。

このvariantに関しては下記の参考資料などを見ていただければと思いますが簡単に言えば、アップロードした画像をそのまま使わずにリサイズ等を行う機能です。
参考

この機能を使えばわざわざ自分でリサイズ処理などを実装する必要がなく、更に初回アクセス時にリサイズした画像を保存して裏で再利用してくれてかなり便利な機能です。
ですが、今回はきの機能が何か悪影響を与えているようです。

これ以上の調査は難しいと判断し、とりあえず似たような症状が他でも起きているのかググってみました。

結果として、AWSのS3などで似たような症状と思われるものが何点か見つかりました。

拙い英語力で斜め読みした所、下記のように判断しました。
(間違っていたらすみません。)

上記を見て、最新版にすれば解決するかと思いましたが、残念ながら6.1はまだリリースされていませんでした・・・。

結論として、varianによる圧縮処理をやめて元の画像を使用する事としました。
元の画像に関して、そもそもアップロード前に手動で画像ツール等でリサイズなどの補正をしているため問題にはならないだろうという判断です。

結果として元の100ms以上かかっていたログは消えて、下記のような1ミリ秒の処理に変更され、体感的に速度が早くなったように感じます。

GCS Storage (1.5ms) Generated URL for file at key: xxxx

という事で、クラウドストレージ(GCS)でActiveStorageで加工した画像を使用する際に処理時間がかかっている事が原因でした。
根本的な対策はせずに機能を使用しないという、微妙な形で対応する事としました。

いずれリリースされるRails6.1では対策がされているようなので、アップデート後にはまた機能を使用したいと思います。

S3やGCSなどクラウドストレージをお手軽に使用できるActive Storageですが、裏で色々と隠蔽してくれているおかげで、逆に見えない箇所で性能に影響を与える事がわかりました。