Heroku上的奇怪的TTFB(第一个字节的时间)问题

Nie*_*ian 22 performance ruby-on-rails heroku newrelic

我们正在改进我们在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
Run Code Online (Sandbox Code Playgroud)

然后我们运行相同的脚本来记录响应时间并得到几乎相同的结果.平均响应时间约为130MS(显然更快,因为它没有击中的应用程序,但仍然60请求了超过400个毫秒和25个请求花了超过1秒.同样,一些16秒钟缓慢请求.

一种解释可能与网络上的慢速跳跃或DNS设置有关,但traceroute的结果看起来非常好.

通过在Heroku上托管的另一个rails 3.2和ruby 1.9.3应用程序上运行响应脚本来确认此结果 - 完全没有奇怪的行为.

DNS设置遵循Heroku的建议.

-

至少我们很困惑.Heroku的路由网络可能会有些腥味吗?为什么我们看到这种奇怪的行为呢?我们如何摆脱它?为什么我们不能在New Relic中看到它?

Nie*_*ian 23

原来它是一种请求排队.有时候,那个Web服务器很忙,而且由于heroku只是随机地将传入的请求随机地路由到任何dyno,然后我可能会在dyno后面的队列中结束,因为例如数据库问题而完全陷入困境.奇怪的是,这在新的遗物中几乎不可察觉(在他们的图表中查看这些东西时取消选中所有其他资源是一个好主意,然后突然出现排队)

编辑21/2 2013:事实证明,在Newrelic中它并不难以察觉的原因是它没有被测量!http://rapgenius.com/Lemon-money-trees-rap-genius-response-to-heroku-lyrics

我们发现这非常令人沮丧,我们最终离开了Heroku,转而使用专用服务器.这使我们的性能提高了20倍,成本的1/10.此外,我必须说我们对Heroku感到失望,他们在发生这种情况时,否认缓慢是由于他们的基础设施,即使我们怀疑并强调了几次.我们甚至得到了这样的答案:

Heroku 28/8 2012:"如果您没有看到New Relic中报告的请求排队或其他缓慢,那么这可能不是服务器端问题.Heroku的内部路由应该花费<1ms.我们的监控系统都没有指示任何目前路由问题."

此外,我们采访了Newrelic,他似乎也没有意识到这个问题,即使他们根据他们自己与Heroku有着非常密切的工作关系.

Newrelic 2012年2月29日:"看起来在Ruby代理的可见性开始之前发生的任何事情都会发生.代理记录的队列时间是从请求进入 dyno 开始的时间,因此在此之前发生减速."

最重要的是,我们最终花费了数小时和数小时来优化不是瓶颈的代码.另外,为了提高我们的表现,还有一个过高的dyno规模,但是我们真正得到的唯一一件事就是来自Heroku和Newrelic的更多收据 - 不是很酷.我很高兴我们改变了.

PS.当时甚至还有一个错误导致所有dynos的新手专业人员受到指控,即使我们(根据Newrelics自己的建议)已禁用对我们后台工作进程的监控.在双方承认错误之前,花了很多时间和许多电子邮件.

PPS.如果您不了解当前正在进行的讨论,那么这里是链接http://rapgenius.com/James-somers-herokus-ugly-secret-lyrics

编辑26/2 2013 Heroku刚刚在他们的时事通讯中宣布,Newrelic发布了一个更新,显然应该对Heroku的情况有所了解.

编辑2013年8月4日 Heroku刚刚发布了关于该主题的常见问题解答

  • 它接近准确.从那时起,我们的服务器容量已经增长得更多,因此现在很难比较.但是我记得我们的平均值.新文物中的服务器加载时间从平均值上下降.1秒+由不良路由(通常为30秒)导致的所有stange延迟到平均150ms的平均值.除此之外,我们现在在背景处理方面存在巨大的产能过剩,我可以轻松地运行多次sidekiq工作,而不是之前的8-10 dynos.我的设置在Hetzner上运行,亲眼看看.我们使用这些http://www.hetzner.de/hosting/produkte_rootserver/ex6s (2认同)
  • 我应该提一下,事情是有代价的 - 如果你遇到问题,对Hetzner没什么帮助 - 软件方面,你完全靠自己,硬件方面它有点好,但响应时间不是很好(通常是1)小时).因此,您需要拥有更多服务器和良好的故障转移设置.然而到目前为止,事情已经变得更稳定,并且对我们来说更好的正常运行时间,那时就是在Heroku上.我必须说,我想念Herokus的支持以及他们所有的好文档和他们漂亮的工具.毕竟他们真的有很多很酷的产品. (2认同)