Мы работаем над улучшением производительности нашего приложения rails, размещенного на Heroku (rails 3.2.8 и ruby 1.9.3). Во время этого мы столкнулись с одной тревожной проблемой, источник которой, кажется, чрезвычайно трудно отследить. Позвольте мне быстро объяснить, как мы столкнулись с проблемой и как мы пытались ее изолировать.
--
Примерно с июня мы наблюдаем странное отставание во времени до первого байта по всему сайту. Проблема очевидна при использовании сайта (иногда приложение не отвечает в течение 10-20 секунд), а также присутствует в водопадном анализе через webpagetest.org. Мы находимся в Дании, но получаем этот результат от любого хоста.
Чтобы подтвердить проблему, мы провели тестовый тест, в котором мы отправили 300 одинаковых запросов на простую страницу и измерили время отклика. Если мы отправим 300 запросов на главную страницу, среднее время ответа составит менее 1 секунды, что довольно хорошо. Что нас пугает, так это то, что 60 запросов занимают вдвое больше времени, а 40 из них занимают более 4 секунд. Некоторые запросы занимают до 16 секунд.
Ни один из этих медленных запросов не отображается в New Relic, который мы используем для мониторинга производительности. Никакой очереди запросов не появляется, и результаты одинаковы, независимо от того, насколько высоко мы масштабируем наши веб-процессы. Тем не менее, мы не могли отрицать, что проблема была вызвана кодом приложения, поэтому мы провели еще один эксперимент, в котором мы отвечали на запрос через промежуточное ПО стойки.
Поместив это промежуточное ПО (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 секунд.
Одно из объяснений может быть связано с медленными переходами в сети или с настройкой DNS, но результаты traceroute выглядят совершенно нормально.
Этот результат был подтвержден запуском скрипта ответа в другом приложении rails 3.2 и ruby 1.9.3, размещенном на Heroku — никакого странного поведения.
Настройка DNS следует рекомендациям Heroku.
--
Мы в замешательстве, если не сказать больше. Может ли быть что-то подозрительное с сетью маршрутизации Heroku? Почему, черт возьми, мы наблюдаем это странное поведение? Как нам от него избавиться? И почему мы не можем увидеть это в New Relic?
