Wir sind dabei, die Leistung unserer Rails-App, die bei Heroku gehostet wird (Rails 3.2.8 und Ruby 1.9.3), zu verbessern. Währenddessen sind wir auf ein alarmierendes Problem gestoßen, bei dem es äußerst schwierig zu sein scheint, die Quelle zu verfolgen. Lassen Sie mich kurz erklären, wie wir das Problem erleben und wie wir versucht haben, es einzugrenzen.

-

Seit ungefähr Juni haben wir überall auf der Site ein seltsames Lag-Verhalten in Time to First Byte festgestellt. Die Probleme ergeben sich aus der Verwendung der Website (manchmal reagiert die Anwendung 10 bis 20 Sekunden lang nicht) und sie ist auch in der Wasserfallanalyse über webpagetest.org vorhanden. Wir sind in Dänemark ansässig, bekommen dieses Ergebnis aber von jedem Gastgeber.

Um das Problem zu bestätigen, haben wir einen Benchmark-Test durchgeführt, bei dem 300 identische Anfragen an eine einfache Seite gesendet und die Antwortzeit gemessen wurden. Wenn wir 300 Anfragen an die Titelseite senden, liegt die mittlere Antwortzeit unter 1 Sekunde, was ziemlich gut ist. Was uns Angst macht, ist, dass 60 Anfragen mehr als doppelt so viel Zeit in Anspruch nehmen und 40 davon mehr als 4 Sekunden. Einige Anfragen dauern bis zu 16 Sekunden.

Keine dieser langsamen Anforderungen wird in New Relic angezeigt, das wir für die Leistungsüberwachung verwenden. Es wird keine Anforderungswarteschlange angezeigt und die Ergebnisse sind gleich, egal wie hoch wir unsere Webprozesse skalieren. Wir konnten jedoch nicht ablehnen, dass das Problem durch den Anwendungscode verursacht wurde, und versuchten es mit einem anderen Experiment, bei dem wir über die Rack-Middleware auf die Anfrage reagierten.

Durch Platzieren dieser Middleware (TestMiddleware) am Anfang des Rack-Stacks haben wir eine Anforderung zurückgegeben, bevor sie überhaupt auf die Anwendung zugegriffen hat, und sichergestellt, dass keine der folgenden Middleware- oder Rails-Apps die Verzögerung verursachen kann.

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

Wir haben dann dasselbe Skript ausgeführt, um die Antwortzeit zu dokumentieren, und haben fast dasselbe Ergebnis erzielt. Die mittlere Antwortzeit betrug ca. 130 ms (offensichtlich schneller, weil die App nicht aufgerufen wurde. Trotzdem dauerten 60 Anforderungen mehr als 400 ms und 25 Anforderungen länger als 1 Sekunde. Wiederum waren einige Anforderungen nur 16 Sekunden lang.

Eine Erklärung könnte im Zusammenhang mit langsamen Sprüngen im Netzwerk oder der DNS-Einrichtung stehen, aber die Ergebnisse von Traceroute sehen vollkommen in Ordnung aus.

Dieses Ergebnis wurde durch Ausführen des Antwortskripts auf einer anderen Rails 3.2- und Ruby 1.9.3-Anwendung, die auf Heroku gehostet wird, bestätigt - überhaupt kein seltsames Verhalten.

Das DNS-Setup folgt den Empfehlungen von Heroku.

-

Wir sind gelinde gesagt verwirrt. Könnte Herokus Routing-Netzwerk faul sein? Warum zum Teufel sehen wir dieses seltsame Verhalten? Wie werden wir es los? Und warum können wir es nicht in New Relic sehen?