Extraño problema de TTFB (tiempo hasta el primer byte) en Heroku

Estamos en el proceso de mejorar el rendimiento de nuestra aplicación de Rails alojada en Heroku (Rails 3.2.8 y ruby ​​1.9.3). Durante esto, hemos encontrado un problema alarmante para el cual la fuente parece ser extremadamente difícil de rastrear. Permítanme explicar rápidamente cómo experimentamos el problema y cómo hemos tratado de aislarlo.

Desde alrededor de junio hemos experimentado un extraño comportamiento de retraso en Time to First Byte en todo el sitio. El problema es obvio al usar el sitio (a veces la aplicación no responde durante 10 a 20 segundos) y también está presente en el análisis de cascada a través de webpagetest.org. Nuestra base está en Dinamarca, pero obtenemos este resultado de cualquier anfitrión.

Para confirmar el problema, hemos realizado una prueba de referencia en la que enviamos 300 solicitudes idénticas a una página simple y medimos el tiempo de respuesta. Si enviamos 300 solicitudes a la página principal, el tiempo de respuesta promedio es inferior a 1 segundo, lo cual es bastante bueno. Lo que nos asusta es que 60 solicitudes toman más del doble de ese tiempo y 40 de ellas toman más de 4 segundos. Algunas solicitudes tardan hasta 16 segundos.

Ninguna de estas solicitudes lentas aparece en New Relic, que utilizamos para el monitoreo del rendimiento. No se muestra ninguna cola de solicitudes y los resultados son los mismos, no importa qué tan alto sea la escala de nuestros procesos web. Aún así, no pudimos rechazar que el problema fue causado por el código de la aplicación, por lo que probamos otro experimento en el que respondimos a la solicitud a través de un middleware de rack.

Al colocar este middleware (TestMiddleware) al comienzo de la stack del rack, devolvimos una solicitud antes de que incluso llegara a la aplicación, asegurando que ninguno de los siguientes middleware o la aplicación de Rails podría causar la demora.

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 

Luego ejecutamos el mismo script para documentar el tiempo de respuesta y obtuvimos prácticamente el mismo resultado. El tiempo de respuesta promedio fue de alrededor de 130 ms (obviamente más rápido porque no llega a la aplicación. Pero aún así, 60 solicitudes tomaron más de 400 ms y 25 solicitudes tomaron más de 1 segundo. De nuevo, con algunas solicitudes tan lentas como 16 segundos.

Una explicación podría estar relacionada con los saltos lentos en la red o la configuración de DNS, pero los resultados de traceroute se ven perfectamente bien.

Este resultado se confirmó al ejecutar el script de respuesta en otros Rails 3.2 y la aplicación ruby ​​1.9.3 alojada en Heroku, sin ningún comportamiento extraño.

La configuración del DNS sigue las recomendaciones de Heroku.

Estamos confundidos por decir lo menos. ¿Podría haber algo raro con la red de enrutamiento de Heroku? ¿Por qué diablos estamos viendo este extraño comportamiento? ¿Cómo nos deshacemos de él? ¿Y por qué no podemos verlo en New Relic?

Resultó que era una especie de cola de solicitud. A veces, ese servidor web estaba ocupado, y dado que heroku simplemente enruta las solicitudes entrantes al azar a cualquier dinamómetro, entonces podría terminar en una cola detrás de un dinamómetro, que estaba totalmente bloqueado debido a, por ejemplo, problemas con la base de datos. Lo extraño es que esto no se notaba en la nueva reliquia (es una buena idea desmarcar todos los demás recursos cuando se visualiza Thins en sus gráficos, luego aparece la cola de repente)

EDITAR 21/2 2013: ¡Resultó que la razón por la que no se notaba en Newrelic era que no se había medido! http://rapgenius.com/Lemon-money-trees-rap-genius-response-to-heroku-lyrics

Esto nos parece muy frustrante, y terminamos dejando a Heroku en favor de servidores dedicados. Esto nos dio un rendimiento 20 veces mejor a un 1/10 del costo. Además, debo decir que estamos decepcionados por Heroku, quien en el momento en que sucedió esto, negó que la lentitud se debiera a su infraestructura a pesar de que lo sospecháramos y lo destacamos varias veces. Incluso tenemos respuestas como esta de vuelta:

Heroku 28/8 2012: “Si no está viendo la cola de solicitudes u otra lentitud reportada en New Relic, entonces esto probablemente no sea un problema del lado del servidor. El enrutamiento interno de Heroku debe durar <1 ms. Ninguno de nuestros sistemas de monitoreo está indicando Problemas de enrutamiento actualmente ".

Además, hablamos con Newrelic, que también parecía ignorar el problema, a pesar de que según ellos mismos tienen una relación de trabajo muy estrecha con Heroku.

Newrelic 29/8 2012: “Parece que todo lo que está causando esto está sucediendo antes de que comience la visibilidad del agente Ruby. El tiempo en la cola que registra el agente es desde el momento en que la solicitud ingresa a un dinamómetro, por lo que la desaceleración está ocurriendo antes de esa fecha”.

La conclusión era que terminamos gastando horas y horas en la optimización del código que no era realmente el cuello de botella. Además, ejecutar con una escala de dinamómetro demasiado alta en un bash desesperado de mejorar nuestro rendimiento, pero lo único que realmente obtuvimos de esto fueron los recibos más grandes tanto de Heroku como de Newrelic, NO FRESCO. Me alegro de que hayamos cambiado.

PD. En ese momento, incluso hubo un error que causó la carga de newrelic pro en TODOS los diálogos, aunque nosotros, (según el propio asesoramiento de Newrelics), habíamos desactivado la supervisión en nuestros procesos de fondo de trabajo. Tomó mucho tiempo y muchos correos electrónicos antes de que el error fuera admitido por ambas partes.

PPS. Si no está al tanto de la discusión actual en curso, aquí está el enlace http://rapgenius.com/James-somers-herokus-ugly-secret-lyrics

EDICIÓN 26/2 2013 Heroku acaba de anunciar en su boletín informativo, que Newrelic ha publicado una actualización que aparentemente debería arrojar algo de luz sobre la situación en Heroku.

EDITADO 8/4 2013 Heroku acaba de publicar una pregunta frecuente sobre el tema

traceroute no es una buena medida de los problemas en la red, es una herramienta que puede encontrar fallas a lo largo de la red, pero no le mostrará la mejor vista.

Intente simplemente colocar una página web estática y pegarla con la dirección IP de su probador de páginas web. Si aún es lento, culpe a la red.

Si por alguna razón es rápido, entonces tienes un problema diferente.