この記事は Akatsuki Advent Calendar 2019 1日目の記事です。
はじめに
アカツキでは Ruby on Rails を使ったゲームサーバを開発・運用しています。ゲームの体験を向上するために、レスポンスタイムは一つの重要な要素となるため、種々のパフォーマンスチューニングを行なっています。今回はその一例として、環境変数を1つ設定するだけで、あるAPIのレスポンスタイムが10%も改善した例をご紹介します。
TL;DR
多数の時刻を含むレコードを扱う Ruby on Rails サーバでは、 TZ 環境変数を設定することで、デフォルトタイムゾーン設定ファイル /etc/localtime へのアクセスが減り、高速化が図れるかもしれません。
効果は Time オブジェクト1個あたり数μsの短縮といったオーダーですが、チリも積もれば山となり、数千個のレコードを処理するAPIではレスポンスタイムが10%近く改善する例もありました。
きっかけ
ある日、モバイルゲームのAPIサーバの負荷テストを大きめのインスタンスサイズのサーバで実施したところ、小さい構成のサーバでは問題なかったAPIのレスポンスタイムが、なぜか数秒から数10秒と、とんでもなく遅くなるという事象が起きました。
その時のシステムの状態を top を確認してみると、CPU使用率の user は数%なのにも関わらず、sys が 95% といった高い値を示しており、アプリケーションではなく OS (Linux) 周りの問題であるようでした。
環境
問題が発生した環境は、AWS EC2の c5.9xlarge インスタンス (36 core) の上にDockerで ruby:2.5 コンテナ(Debian Stretchベース)を立て、その中でRailsサーバーを動かしており、そこに多数並列でHTTPリクエストを送り込んでいた、という状況です。
Railsのサーバとして、unicorn が複数プロセス動いており、各プロセスはシングルスレッドで動作する構成です。つまり、スケーラビリティの問題の原因になりやすい Ruby の GIL (グローバルインタプリタロック) のせいではありません。
詳しく分析してみる
このセクションでは、 Linux カーネルや Ruby の動作を調べた内容を説明していきます。低レイヤーに踏み込む話になるので、早く結果を知りたいという方は、次のセクションの「対策とおまけ効果」まで読み飛ばして構いません。
プロファイラをかけてみる
こういったときには、どこでCPUが使用されているかをプロファイラで調べてみると有効です。そこでまず、 Linux のプロファイラである perf を使用してみます。
問題発生中に sudo perf top -g を実行すると、CPU が使われている場所のプロファイルが C の関数単位でリアルタイムに表示されます。
以下は95%以上を占める高い __xstat64 から下位の関数を展開していったところです。なお __xstat64 はファイルの変更日時などの情報を取得するglibcの関数です。
Samples: 30K of event 'cycles', Event count (approx.): 32976632083
Children Self Shared Object Symbol
- 95.21% 0.02% libc-2.24.so [.] __xstat64
- __xstat64
- 95.04% entry_SYSCALL_64
- do_syscall_64
- 94.14% __do_sys_newstat
- 94.03% vfs_statx
- 92.21% filename_lookup
- 92.14% path_lookupat
- 66.85% link_path_walk.part.39
- 63.60% walk_component
- 22.86% lookup_fast
- 22.75% __d_lookup
+ _raw_spin_lock
- 21.11% path_parent_directory
- 19.89% dget_parent
- lockref_get_not_zero
+ _raw_spin_lock
+ 1.23% dput
- 19.53% dput
+ 18.02% _raw_spin_lock
1.38% lockref_put_return
+ 3.00% inode_permission
- 22.98% walk_component
- 20.49% dput
+ 19.17% _raw_spin_lock
1.14% lockref_put_return
+ 2.41% lookup_fast
+ 1.70% trailing_symlink
+ 0.57% terminate_walk
+ 0.88% path_put
詳細は割愛しますが、path_lookupat 関数を始め、主に Linux カーネル内のファイルパスを辿る関数群で時間を消費しているようです。さらに辿っていくと、主要因としていろんなところで _raw_spin_lock が出てきました。これは、 Linux カーネルのスピンロック (他のCPUと排他が取れるまで無限ループしながら待つロック方式) の関数で、1つのコアしか同時に処理を行えません。何らかの同じリソースの取り合いが全コアで発生し、コア数が多い分、より激しく競合が発生した結果、アプリケーションの処理が遅々として進まないほどに性能が低下してしまったと考えられます。
では一体何を奪い合っているのでしょうか?
システムコール呼び出しを見てみる
アプリケーションがこの時何をしているのかを調べてみます。
strace -p <rubyのPID>
を実行して何のシステムコール呼び出しているかを調べてみると、どのプロセスも、
stat("/etc/localtime", ...)
stat("/etc/localtime", ...)
stat("/etc/localtime", ...)
...
と、ひたすら /etc/localtime というファイルに対して stat システムコールを呼び出していることがわかりました。同じファイルに対して全コアでロックを取りあっているため、激しく競合が発生しているようですね。
このファイルは、システムのデフォルトのタイムゾーン情報を格納するものです。
ファイルと言いましたが、正確にはrubyコンテナではシンボリックリンクになっています。
UTCをデフォルトタイムゾーンとして使用していますので、リンク先は /usr/share/zoneinfo/Etc/UTC を指しており、さらにこれもシンボリックリンクで ../UCT を指しています。
また同様に ltrace をアタッチしてみると、tz_set, localtime_r などの時刻関連の関数がひたすら呼び出されていました。この中で先ほどの stat システムコールが呼び出されています。
stat システムコールということは、このファイルの内容を読んでいるわけではありません*1。もしかしたらいつの間にかデフォルトのタイムゾーンが前回から変更されているかもしれないので、再読み込みか必要かどうかを調べるために、更新日時を調べているのです。( → glibc の __tzfile_read() )
Ruby on Railsはその時何をしていたのか？
では、なんでこんなに localtime_r が呼ばれているのでしょうか？
実は、負荷テストのシナリオの中に、数千件のレコードを MySQL から取得して読み込む API がありました。これらのレコードにはそれぞれ数個の日時が含まれていました。加えて、ActiveRecordの慣例に従って、各レコードには created_at, updated_at カラムがあり、作成・更新時刻を格納しています。
そしてこれらを ActiveRecord が Time(WithZone) クラスとしてインスタンス化する際に、 localtime_r が呼び出されていたのでした。
localtime_r は Time.new ごとに1回呼ばれるだけではなかった
しかも、 localtime_r は Time のインスタンス化で一回呼び出されるだけではありませんでした。
strace ruby -e 'puts; p Time.new'
などと実行してシステムコールの呼び出され方を見てみると、以下のようになりました。*2
- Time.new → statが1回呼ばれる
- Time.new(2019,7,1,0,0,0,"+09:00") → なぜかstatが2回呼ばれる
- Time.new(2019,7,1,0,0,0) → なぜかstatが4回くらい呼ばれる(timezoneを取得するため?)
Ruby の time.c を見てみると、 find_time_t 関数にてシステムの localtime_r に指定時刻の2時間前後の時刻を与えて、何が返ってくるかを調べています。これはどうやら、夏時間の切り替わりの際には同一の時刻が2回ある場合があるので、そういうときに必ず決まった側を返すための処理のようでした。
それにしても、このコードには多数の #ifdef があり、Ruby を様々な環境で動かすための苦労が窺われます……。
対策とおまけ効果
man tzset を見てみると書いてあるのですが、 環境変数 TZ に値が設定してあれば、 /etc/localtime は読まれなくなり、この問題も発生しなくなります。
そこで、例えば TZ=UTC と設定すると、 stat 等のファイルアクセスはなくなります。
これは今回きっかけとなった負荷テストで見られたような大規模サーバでのスケーラビリティの解決はもちろんですが、たとえ小さなサーバであっても、システムコールの発行自体がなくなることで性能向上を期待できます。
具体的に、先ほどのruby:2.5.1コンテナ内で、シングルプロセスのみで試してみましょう。
$ irb
irb(main):001:0> t = Time.now; 100000.times { Time.new(2019) }; Time.now - t
=> 1.027663412
# 環境変数を設定
irb(main):002:0> ENV['TZ'] = 'UTC'
=> "UTC"
irb(main):003:0> t = Time.now; 100000.times { Time.new(2019) }; Time.now - t
=> 0.135658217
なんと7〜8倍の高速化です!
Linuxディストリビューションによっては、 /etc/localtime はシンボリックリンクでなく実ファイルであることもあります。
例えばAmazon Linux 2では /etc/localtime は実ファイルとなっていますが、このケースでも測定してみました。
irb(main):001:0> t = Time.now; 100000.times { Time.new(2019) }; Time.now - t
=> 0.57196811
TZ を設定すると先の例と同程度の時間になり、約4倍の改善となりました。シンボリックリンクのパスを辿らなくて済む分、軽微な影響となるようです。
もちろんこれは Time.new のみの倍率であって、1回1回は高々数μsといったオーダーの効果です。しかし、数千レコードを扱うようなAPI*3だと、積もり積もってAPI全体のレスポンスタイムが10%程度も改善するケースが実際にありました。
まとめ
Ruby on Railsで大量の時間を含むレコードを扱う際、 TZ 環境変数が設定されていないと、Time オブジェクトの初期化のたびに複数回 /etc/localtime に対して stat システムコールが呼び出されるため、性能が低下します。特に /etc/localtime がシンボリックリンクである場合や、コア数の多いサーバ環境ではカーネル内のスピンロックのために影響が顕在化しやすくなります。この現象は特にRuby 2.5までにおいて顕著です。
TZ 環境変数を適切な値に設定することで、これを避けて、時刻を扱う処理を高速化することができます。
今後のRubyへのフィードバック
さて、これで本問題は一段落なのですが、 こうした手間をかけなくともRuby自体で高速に動作してくれたら嬉しいですよね。アカツキに技術顧問として加わって頂いた小崎資広さんに、この現象についてRubyのアップストリームで根本的な改善ができるのではないかと、コミュニティで議論していただいています。
詳しくは別の記事でご紹介したいと思いますので、乞うご期待。
→ 記事が公開されました! ぜひ併せてお読みください。
