MemcachedのEvictionを解消した話

初めに

MemcachedによるEvictionが発生し、調査、解消する機会がありました。同じようなエラーに遭遇している人の助けになればと思い、記事を作成しました。ホスト名やキャッシュのキー名などは適宜マスクし、コードも重要な箇所を除いて適当な名称に置き換えているのでご承知おきください。

環境について

Eviction が発生していたプロダクトの環境は以下の通りです。

• Rails(6.1.5)
• Memcached(1.4.34)
  • Amazon ElasiCacheを利用していました。

Railsのcache_storeにMemcachedを利用しています。当然、プロダクト全体としては使用している技術は他にもありますが、この記事に関係のない箇所なので割愛します。

発生していた事象

Evictionの発生を外部ツールで監視しているのですが、ある日を境に突然大量に発生し始めました。

Evictionについて

AWSのAmazon ElasiCacheの説明^[1]が分かりやすいので引用します。

新しく書き込むための領域を確保するためにキャッシュが排除した、期限切れではない項目の数。

つまり、

• Memcashedが新しくデータを書き込もうとする。
• Memcashedの書き込み容量足りない。
• 仕方ないので、期限が切れていないキャッシュを削除する。
• Evictionが発生する。

と言った流れでEvictionが発生します。Evictionが発生することで特定の機能が使えなくなるといった事はなかったのですが、キャッシュとして正しく機能してないため、原因を調査することにしました。

調査したこと

コードの調査

まずはMemcachedにどのようなデータを保存しているのかをプロダクトのコード上から調査しました。RailsではMemcachedにデータを保存する場合にRails.cache.hogehogeと言った形でMemcachedにアクセスできるので、grepしてみましたが、特にそれっぽいものは見つけられませんでした😇

コードを読んでいても埒が開かなかったので、実際にMemcachedの中に保存されているデータを確認しました。

Memcachedの中の調査

Memcachedの中身を確認する方法はいくつかありますが、ここではncコマンドを利用して確認しました。Memcachedのデータはslabと呼ばれる単位でデータが保存されており、以下のように中身のデータを確認していきました。^[2][3]

echo 'stats items' | nc memcached.hogehoge 11211 | grep 'number '
# itemsの後ろがslabの番号を表し、numberの後ろが格納されている　item数を表します。
STAT items:1:number 658
STAT items:2:number 13425
STAT items:3:number 396
STAT items:4:number 9
STAT items:5:number 3180

echo 'stats cachedump 5' | nc memcached.hogehoge 11211
# ITEM キー名 [容量;　expireの時刻]を表します。
# expireの時刻はUnix Timeです。
ITEM hogehoge:aaaaaaaa [83 b; 1528513098 s]
ITEM hogehoge:bbbbbbbb [83 b; 1528513098 s]

とりあえず、見れるだけのデータをncコマンドを使って確認しました。すると、expireが0になっているデータがあることに気が付きました。

echo 'stats cachedump 1' | nc memcached.hogehoge 11211
ITEM hogehoge:abcdefg [100 b; 0 s]

調べてみると一件だけではなく、何十件もあったので、なんとなく怪しそうだと思い、expireが0のデータの扱いを調べました。Memcashedのwikiには以下のように記されています。

An expiration time, in seconds. '0' means never expire. Can be up to 30 days. After 30 days, is treated as a unix timestamp of an exact date.

つまりexpire = 0は決して期限が切れないデータとして扱われるようです。この段階で、以下のような流れでEviction が発生していたのではと仮説を立てました。

• 何かしらが原因で、expire = 0のデータが紛れ込む。
• expire = 0なので、いつまで経っても削除されず、Memcashedの容量がexpire = 0のデータでいっぱいになる。
• 新しいデータを書き込もうとするが容量が足りない。
• 仕方ないので、期限が切れてないデータ(恐らく、expire = 0も含む)を削除する。
• Eviction が発生する。

改めてコードの調査

expire = 0にしてデータをキャッシュしている箇所をコード上から探してみましたが、そのような箇所はありません。コード中にbinding.pryを仕込み、キャッシュしている箇所をデバッグしました。詳細は割愛しますが、原因となるコードを見つけました。

https://github.com/rails/rails/blob/v6.1.5/activesupport/lib/active_support/cache/mem_cache_store.rb#L147-L159

150行目のoptions[:expires_in].to_iが肝です。expires_inがnilだった場合に、0になります。改めてプロダクトのコードを見てみると、以下のような箇所が見つかりました。

sample

def hoge(expires_in: nil)
  <省略>
  Rails.cache.fetch(hogehoge,expires_in: expires_in) do
  <省略>
  end
end

expires_inの初期値にnilを入れているのが原因でした。ということで、初期値を適当な日付に変更してあげたら事象は解決しそうです。

なぜ発生したのか

事象が発生した直前にRailsのcache_storeをdalli_storeからmem_cache_storeに変更したのが原因です。mem_cache_storeに変えたことで上記のコードを利用するようになり、Evictionが発生し始めました。

対応について

expires_inの初期値を適当な日付に変更してあげればEvictionは発生しなくなりましたが、まだやらなくてはいけない事が残っています。expire = 0になったキャッシュの削除です。ゴミとなるデータが残ってしまうのもあれなので、Rails.cache.clearして削除しました。

補足(Rails.cache.clearの挙動について)

対応自体は以上で終わりでしたが、Rails.cache.clearの挙動が一部わかりづらいので補足しておきます。Rails.cache.clearを実行してもすぐにメモリが全て解放される訳ではありません。これはMemcachedの仕様によるものです。Rails.cache.clearは内部でMemcachedのコマンドの一つであるflush_allを実行します。

https://github.com/rails/rails/blob/53410537594be0c0a528cff53dce433dd386cb6a/activesupport/lib/active_support/cache/mem_cache_store.rb#L129-L133

そして、memcachedのリポジトリにはflush_allの説明は以下のように書かれています。

https://github.com/memcached/memcached/blob/046c4bb5d8498420c13e5357c8299b60952b2595/doc/protocol.txt#L1728-L1739

つまり、flush_allを実行すると、キャッシュを無効化し(恐らく、expireを実行時刻にセットする)新しいitemが追加されるに伴い徐々に削除されていく挙動のようです。

終わりに

Railsのキャッシュやmemcached事態に深く踏み込んで調べたことがなかったので良い経験になりました。

脚注

1. https://docs.aws.amazon.com/ja_jp/AmazonElastiCache/latest/mem-ug/CacheMetrics.Memcached.html

2. ncコマンドの使い方は検索すれば記事が出てくると思いますので、興味がある方は検索してみてください。

3. itemsで表示される内容の詳細はこちらが参考になります。https://github.com/memcached/memcached/blob/046c4bb5d8498420c13e5357c8299b60952b2595/doc/protocol.txt#L1463 ↩︎