Jesteśmy w trakcie ulepszania wydajności naszej aplikacji szyny hostowanej na Heroku (rails 3.2.8 i ruby ​​1.9.3). W tym czasie natknęliśmy się na jeden alarmujący problem, którego śledzenie wydaje się niezwykle trudne. Pozwólcie, że szybko wyjaśnię, w jaki sposób doświadczamy problemu i jak próbowaliśmy go wyizolować.

-

Od około czerwca doświadczyliśmy dziwnych zachowań związanych z opóźnieniami w Time to First Byte w całej witrynie. Problemy są oczywiste z korzystania z witryny (czasami aplikacja nie odpowiada przez 10-20 sekund), a także występuje w analizie wodospadu za pośrednictwem webpagetest.org. Mamy siedzibę w Danii, ale otrzymujemy ten wynik od dowolnego hosta.

Aby potwierdzić problem, przeprowadziliśmy test porównawczy, w którym wysłaliśmy 300 identycznych żądań do prostej strony i zmierzyliśmy czas odpowiedzi. Jeśli wyślemy 300 wniosków na pierwszą stronę, średni czas odpowiedzi wynosi poniżej 1 sekundy, co jest dość dobrym wynikiem. To, co nas przeraża, to fakt, że 60 żądań zajmuje więcej niż dwa razy więcej, a 40 z nich zajmuje więcej niż 4 sekundy. Niektóre żądania trwają nawet 16 sekund.

Żadne z tych powolnych żądań nie pojawia się w New Relic, którego używamy do monitorowania wydajności. Nie pojawia się kolejkowanie żądań, a wyniki są takie same bez względu na to, jak wysoko skalujemy nasze procesy internetowe. Mimo to nie mogliśmy odrzucić tego, że problem był spowodowany kodem aplikacji, więc spróbowaliśmy innego eksperymentu, w którym odpowiedzieliśmy na żądanie za pomocą oprogramowania pośredniego.

Umieszczając to oprogramowanie pośrednie (TestMiddleware) na początku stosu racków, zwróciliśmy żądanie, zanim jeszcze trafiło ono do aplikacji, upewniając się, że żadne z poniższych programów pośrednich lub aplikacji szynowych nie może spowodować opóźnienia.

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

Następnie uruchomiliśmy ten sam skrypt, aby udokumentować czas odpowiedzi i uzyskaliśmy prawie taki sam wynik. Średni czas odpowiedzi wynosił około 130 ms (oczywiście szybszy, ponieważ nie trafił w aplikację. Ale nadal 60 żądań zajęło ponad 400 ms, a 25 żądań zajęło ponad 1 sekundę. Ponownie, niektóre żądania były tak powolne, jak 16 sekund.

Jedno z wyjaśnień może dotyczyć powolnego przeskoku w sieci lub konfiguracji DNS, ale wyniki traceroute wyglądają doskonale.

Wynik ten został potwierdzony przez uruchomienie skryptu odpowiedzi na innej aplikacji szyny 3.2 i ruby ​​1.9.3 hostowanej na Heroku - bez dziwnych zachowań.

Konfiguracja DNS jest zgodna z zaleceniami Heroku.

-

Jesteśmy co najmniej pomieszani. Czy w sieci routingu Heroku może być coś podejrzanego? Dlaczego do diabła widzimy to dziwne zachowanie? Jak się tego pozbyć? I dlaczego nie możemy tego zobaczyć w New Relic?