現在、Herokuでホストされているrailsアプリ(rails3.2.8およびruby1.9.3)のパフォーマンスを改善しているところです。この間に、ソースを追跡するのが非常に難しいと思われる1つの憂慮すべき問題に遭遇しました。問題がどのように発生し、どのように問題を切り分けようとしたかについて簡単に説明します。
-
6月頃から、サイト全体でTime toFirstByteで奇妙なラグ動作が発生しています。このサイトを使用すると問題が明らかになり(アプリケーションが10〜20秒間応答しない場合もあります)、webpagetest.orgを介したウォーターフォール分析にも問題があります。私たちはデンマークに拠点を置いていますが、この結果はどのホストからも得られます。
問題を確認するために、ベンチマークテストを実行しました。このテストでは、300個の同一のリクエストを単純なページに送信し、応答時間を測定しました。フロントページに300のリクエストを送信した場合、応答時間の中央値は1秒未満であり、これはかなり良好です。私たちを怖がらせるのは、60件のリクエストがその2倍以上かかり、そのうち40件が4秒以上かかることです。一部のリクエストには16秒ほどかかります。
これらの遅いリクエストはいずれも、パフォーマンスの監視に使用するNewRelicには表示されません。リクエストキューは表示されず、Webプロセスをどれだけ大きくしても結果は同じです。それでも、問題の原因がアプリケーションコードであることを否定できなかったため、ラックミドルウェアを介してリクエストに応答する別の実験を試みました。
このミドルウェア(TestMiddleware)をラックスタックの先頭に配置することで、アプリケーションにヒットする前にリクエストを返し、次のミドルウェアやRailsアプリが遅延を引き起こさないようにしました。
Middleware setup:
$ heroku run rake middleware
use Rack::Cache
use ActionDispatch::Static
use TestMiddleware
use Rack::Rewrite
use Rack::Lock
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use Rack::Sendfile
use ActionDispatch::Callbacks
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::DalliStore
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use ActionDispatch::Head
use Rack::ConditionalGet
use Rack::ETag
use ActionDispatch::BestStandardsSupport
use NewRelic::Rack::BrowserMonitoring
use Rack::RailsExceptional
use OmniAuth::Builder
run AU::Application.routes
次に、同じスクリプトを実行して応答時間を文書化し、ほぼ同じ結果を得ました。応答時間の中央値は約130ミリ秒でした(アプリにヒットしないため、明らかに高速です。ただし、60リクエストは400ミリ秒以上、25リクエストは1秒以上かかりました。また、一部のリクエストは16秒ほど遅くなりました。
1つの説明は、ネットワークまたはDNSセットアップの低速ホップに関連している可能性がありますが、tracerouteの結果は完全に問題ないように見えます。
この結果は、Herokuでホストされている別のrails3.2およびruby1.9.3アプリケーションで応答スクリプトを実行したことで確認されました。奇妙な動作はまったくありません。
DNSの設定は、Herokuの推奨事項に従います。
-
控えめに言っても混乱しています。Herokuのルーティングネットワークに何か怪しいものはありますか?なぜ私たちはこの奇妙な行動を見ているのですか?どうすればそれを取り除くことができますか?そして、なぜNew Relicでそれを見ることができないのですか?