起動した直後のpumaプロセスのレスポンスタイムがどのくらい遅いか調べる

前に僕が関わっていたpumaを使ったrailsアプリケーションのプロダクトで、激しいメモリブロートが常に発生しており、10分起きにpumaプロセスを再起動する、というワークアラウンドが常態化していました。(やばい)
Railsプロセスの起動直後ってRDBのスキーマがロードされていないし、遅延読み込みしているような実装があると、初回リクエストでのレスポンスが遅くなることは明らかです。

幸い、このアプリケーションは業務システムなのでメディアのようなスパイクが来ることは稀ですし、サーバが多少ダウンしていても許容できる設計になっていたので、この状態で3年くらい経過していました。したがって、クリティカルな問題ではないことは明らかでした。

しかし、現在のユーザ数やソフトウェアのバージョンで問題になっていないだけで、今後足かせになることは目に見えています。直すにしてもどのくらい遅いのかを可視化しようと考えました。

できた実装が下記です。

class FirstRequestMarker
  def initialize(app)
    @app = app
  end

  def call(env)
    if Thread.current[:first_request]
      NewRelic::Agent.add_custom_attributes(first_request_thread: 0)
    else
      Thread.current[:first_request] = true
      NewRelic::Agent.add_custom_attributes(first_request_thread: 1)
    end
    if defined?($first_request)
      NewRelic::Agent.add_custom_attributes(first_request_process: 0)
    else
      $first_request = true
      NewRelic::Agent.add_custom_attributes(first_request_process: 1)
    end
    @app.call(env)
  end
end

Rails::Application.config.middleware.use(FirstRequestMarker)

rack middlewareを使ってThreadとProcessのそれぞれでグローバルな領域を使って初回リクエストなのか判定しました。その判定結果をNew Relicにメトリクスを送信しており、New Relic Query Launguageで可視化することが可能になりました。

この実装で使っている Thread.current ですが、pumaは1リクエスト毎に変数を初期化しません。便利。
実際にその実装を本番投入して測定した結果、起動直後のプロセスのレスポンスは3秒くらい遅い結果になりました。

余談

上記でスキーマのロードが遅い、というのを書いていますが、それを解決する方法がRailsに用意されています。それがschema cacheです。
schema cacheの導入を検討したんですが、ジュニア寄りに近い人が増えてきたので、schema cacheのように可読性のないymlに誤った変更を入れられるとサービスがダウンする可能性があると考えてschema cacheの投入を見送りました。今思えばCIでチェックすればよさそう。

おわり