先にまとめると

ディスクI/Oに高い負荷をかけるシステムでNVMeデバイスを使うときweekly cron jobでfstrimが走る状況になってたら停止しろ
じゃないとfstrimが走った瞬間にI/Oパフォーマンスが刺さって死ぬ
fstrimを停止するならdiscard mount optionを有効化しろ、ただしその状態でのI/O性能で問題ないかどうか測っておけ
discard mount optionを有効化しても大きいファイルの削除には気をつけろ、プチfstrimみたいになるぞ
追記されるばかりで大きくなるファイル(そして削除されるファイル)はNVMeじゃないデバイスに置いとけ

高I/Oスループットを期待するシステムでのNVMeとfstrim

社内で小さめのインスタンスを多く並べてトラフィックを捌いてたのを色々要件があって大きめのインスタンスにまとめるようなシステムアップデートをやってたんだけど、ローカルファイルシステムに大量の小さいファイルを書く構造をとって、そこを高I/OパフォーマンスなデバイスつまりNVMeを使うことで全体の性能を上げる、みたいな構成にした。

ベンチマークをとってもだいぶ良い感じだったのであれこれ試してから万全の体制……のつもりで本番投入したところ、見事に刺さった。突然ストレージのI/Oパフォーマンスが劇的に下がって全プロセスがスタックするというトラブルが、しかも複数のAWSリージョンでなぜか同時*1に起きた。初回は混乱したままインスタンス増加や入れ替えなどを行って原因がわからねーなーと思ってたんだけど、どうも見てると毎週同じ曜日の同じ時刻に発生している。なんだこれは。

で、調べてみたらこの時刻は weekly crontab のジョブが実行されるよう /etc/crontab が設定されていて*2、このタスクのひとつとして /etc/cron.weekly/fstrim というやつがあって、これが実行開始されたあとストレージI/Oのパフォーマンスが劇的に悪化するという現象が確認できた。

fstrimがなんなのか大雑把に言うと、SSDやNVMeはデバイス側で使用中のブロックを管理しているが、ファイルシステムは普通ファイル削除時にはファイルシステムのメタデータを削除するだけなので、デバイス側の使用中ブロック情報との間で齟齬が生まれる。fstrimコマンドはこれを解消するために、使用しなくなったブロックをデバイスに通知するためのTRIM命令をまとめて発行するコマンドだ、と自分は理解している。あとは他の解説とかを読んでくれ。例えばAWSのドキュメント "インスタンスストアボリュームの TRIM のサポート"にもこのあたりのことが書いてあって、fstrimを当たり前に使え、となっている。で、I/O負荷がそう高くない普通の*3システムであれば、ヒマなときにやっとけばいいだろうということで、日曜早朝*4に実行するというcron jobの設定が行われていたのだった。

しかし自分の手元のこのシステムにおいては、ものすごい勢いでファイルを作っては削除してを繰り返す。そのパフォーマンスを担保するためにNVMeデバイスを使ってるんだから当然とも言える。そして大量にファイルが削除されているということはTRIMされるブロックもものすごい量に及ぶため、fstrimを実行した瞬間に大量のTRIMオペレーションが実行されて該当デバイスおよびファイルシステムのI/Oレイテンシが激増、システム全体が死亡するという状況になっていた。ステージングなどの環境で気付けなかったのは、fstrimによるパフォーマンスの低下はブロックデバイスへの書き込み量に顕著に依存する、ということによる。本番環境のようなトラフィックが無い環境ではfstrimによる影響が軽微な範囲で収まってしまい、気付くのが困難だったためだ。

f:id:tagomoris:20190624102638p:plain — fstrimが走った瞬間にloadavgが激増して死亡の図

ということで、ファイルシステムでの高スループットI/Oを期待したシステムでfstrimが起動し、その瞬間I/Oパフォーマンスが劇的に低下して無事死亡することになっていた。これ、普通に他所でも起きるんじゃないのかなあ。AWSでNVMeのあるインスタンス使う人って高いI/O性能を期待する人が多いんだろうから、ドキュメントがfstrim実行しろってのは大丈夫なのかと思うけど。

discard mount optionの有効化と次なるI/O性能低下

ところでfstrimについて調べると出てくるドキュメントにはdiscardというmount optionについての記述が出てくる。これはファイルを削除したときにすぐにTRIMオペレーションをブロックデバイスに対して発行するためのもので、当然だがデバイスへの命令が増えるということは、全体のI/Oスループットはいくらか下がる。このためか、例えばRHEL8のドキュメントなどを見ると、避けられない場合を除いてはfstrimによるバッチ処理を推奨している……が、正直これもどうなんだと思う。一般的にコンピュータシステムの性能をコントロールしやすいのは、時々やってくる高負荷のスパイクよりも、圧倒的に、普段の平均的に少し低い性能のほうだ。予測もコントロールもしやすい。しかもfstrimによる負荷はどのくらいファイルが削除されたか、という極めて変動しやすい要素に依存しているため、事前に予期するのは不可能といっていいと思うんだけど。

ということで、普通にNVMeデバイスを使用するシステムを運用するなら、discard mount optionは有効にするべきだと思う。ので、してみた。もちろんdiscard mount optionによるI/Oスループットの低下には注意する必要がある。各種メトリクスを監視しつつ、本番トラフィックからいつでも外せるようにして注意深くやってみた。が、また変なことが起きた。全体の性能は問題ないものの、今度は毎時で小さいスパイクが発生するようになってしまった。fstrimによるほど致命的ではないが、本番トラフィックに晒しておくにはちょっとマズい感じのやつ。

f:id:tagomoris:20190624104106p:plain — 毎時loadavgがちょっと上がるの図

f:id:tagomoris:20190624104133p:plain — 毎時nginxのwaiting queueがちょっと伸びるの図(別時間)

これがなんなのかと悩んでみたんだけど、発生時間を手がかりに調べてたら、わかった。crontabによるhourly cronの起動時刻で、何が起きていたかというとlogrotateだった。いやー、まさかねー、って感じだったよ。

discard有効ボリュームにおけるアクセスログのrotate

まさか現代のマシンでlogrotateの負荷が問題になるか? と思ってしばらく自分も混乱していた。はるかな大昔はサーバのCPUコア数も少なく、その少ないコアがlogrotate時のgzip圧縮で持っていかれて全体のパフォーマンスが低下する、みたいなことを経験したことがある。そんなことが現代でまた起きるか? みたいな感じ。

まさか現代のマシンにおいてlogrotateの負荷を気にする日がまた来ようとは
— tagomoris (@tagomoris) June 7, 2019

実情として、このサーバ(で動いてるnginx)が処理してるトラフィックはそれなりにあるので、アクセスログについてはローカルストレージでの保存期間はとらず、hourlyでlogrotateにかけ、また保存世代数はゼロにしてある*5。これでも毎時40GBくらいの量にはなっている。

で、logrotateがこのアクセスログをrotateするということは、つまり、40GBぶんのブロックに対して一気にTRIMを実行する、ということだったのです。discard mount optionが有効の場合は。これに気付いたときは割とがっくりきた。discard mount optionを有効化することでBatch TRIMから逃げられたと思っていたのに、アクセスログのせいでMicro Batch TRIMとでも言うべきものが起きていたのだった。これが即座に原因だと断定できなかったんだけど、その理由はファイル削除のタイミングとI/Oパフォーマンスの低下のタイミングが微妙にズレることがあるせいだった。これはTRIMオペレーションが実際に実行されるのは非同期化されており、ファイルの削除から少しのタイムラグがあるケースがあるためのようだった。

さてこれが分かれば結論は簡単で、アクセスログをNVMeじゃないデバイスに置いてやればいい。TRIMオペレーションが必要なければこの問題は起きない。問題のインスタンスにアクセスログ用の領域を確保したEBSボリュームをアタッチして、そこにログを書くよう変更してやった。解決!*6

まとめ

NVMeデバイスは高I/Oスループットを発揮できて便利だが、安定したスループットを期待したいのならdiscard mount optionを有効にして運用しよう。またそのデバイス上での巨大なファイルの削除は避けるべきで、そのような例としてはアクセスログなどがある。気をつけよう。

*1:日曜午後3時45分過ぎ

*2:なお全インスタンスのタイムゾーンはUTCにセットされているため、使用中の全リージョンで同一のタイミングでこのジョブが実行されていた

*3:サーバ用途でない

*4:日本時間で15:47はサーバのローカルタイム(UTC)で6:47である

*5:余談だが、このログはFluentdで即座に読み出して外に転送・保存しているので、この運用で良いのです

*6:なお選択肢としては、NVMeデバイスにアクセスログを書きつつもっと頻繁にlogrotateする、という手もなくはない。しかし結局負荷のスパイクの深刻さがファイルサイズに影響されるという状況は変わっておらず、将来的にアクセスログの成長速度がさらに増加したときにトラブルを起こすという潜在的な危険を抱えたままになるので、自分としてはその手段は避けたほうがよいと思う。