MemcachedのEviction accurを解消した話

初めに

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

環境について

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

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

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

発生していた事象

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

Evictionについて

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

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

つまり、

• Memcachedが新しくデータを書き込もうとする。
• Memcachedの書き込み容量足りない。
• 仕方ないので、期限が切れていないキャッシュを削除する。
• 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のデータの扱いを調べました。Memcachedの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 accurが発生していたのではと仮説を立てました。

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

改めてコードの調査

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

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