我们正在改进托管在 Heroku 上的 rails 应用程序的性能(rails 3.2.8 和 ruby 1.9.3)。在此期间,我们遇到了一个令人担忧的问题,其来源似乎极难追踪。让我快速解释一下我们是如何遇到这个问题的,以及我们是如何尝试隔离它的。
--
自 6 月左右以来,我们在整个网站上都经历了 Time to First Byte 的奇怪滞后行为。使用该站点时问题很明显(有时应用程序在 10-20 秒内没有响应),并且它也存在于通过webpagetest.org 进行的瀑布分析中。我们位于丹麦,但可以从任何主机获得此结果。
为了确认这个问题,我们执行了一个基准测试,我们将 300 个相同的请求发送到一个简单的页面并测量响应时间。如果我们向首页发送 300 个请求,则中位响应时间低于 1 秒,这是相当不错的。让我们害怕的是,60 个请求花费的时间是原来的两倍多,其中 40 个请求花费的时间超过 4 秒。有些请求需要长达 16 秒。
这些缓慢的请求都没有出现在我们用于性能监控的 New Relic 中。无论我们扩展 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 秒。
一种解释可能与网络上的慢跳或 DNS 设置有关,但 traceroute 的结果看起来完全没问题。
这个结果通过在 Heroku 上托管的另一个 rails 3.2 和 ruby 1.9.3 应用程序上运行响应脚本得到证实——根本没有奇怪的行为。
DNS 设置遵循 Heroku 的建议。
--
至少可以说我们很困惑。Heroku 的路由网络会不会有问题?为什么我们会看到这种奇怪的行为?我们如何摆脱它?为什么我们不能在 New Relic 中看到它?