Cómo mejoramos 350% el tiempo por transacción de un sitio ya en marcha
Un poco de historia.
Hace ya aproximadamente 5 años tuve la oportunidad de participar en el inicio de un gran proyecto, fue un gran reto a nivel de desarrollo, diseño y planificación. Este proyecto con el pasar del tiempo se fue convirtiendo en uno de los más importantes para nuestra empresa.
El mismo ha venido creciendo, cada día hay nuevos requerimientos por parte del cliente, lo que ha representado un gran reto para nuestro equipo de desarrollo. Se ha agregado gran cantidad de funcionalidades custom y siempre se ha tratado de hacer de manera óptima y eficiente para mantener el proyecto en un estado saludable.
Dado que este proyecto se inició hace ya 5 años, se utilizaron técnicas y metodologías de desarrollo no tan óptimas, ya fuera por desconocimiento o a falta de otra mejor solución. Estos detalles de desarrollo se fueron juntando con otros de las siguientes etapas del proyecto, provocando que el sitio no tuviera el mejor rendimiento.
Pero, ¿Cómo descubrimos el problema?
Como ya se mencionó, el sitio tenía algunos problemas de rendimiento, pero estos problemas para nosotros no eran tan evidentes ya que como desarrolladores no somos usuarios habituales del sitio y, aunado a esto, el cliente tampoco nos daba feedback al respecto, entonces, ¿Cómo descubrimos que teníamos un problema?. Fue después de varios años de que el sitio estaba en desarrollo constante y cuando estábamos por iniciar una nueva etapa de grandes cambios que empezamos a tomar más en cuenta el rendimiento de las funcionalidades Legacy (desarrolladas en la primera iteración del proyecto) ya que íbamos a hacer cambios sobre ellas.
El primer paso que tomamos fue empezar a hacer un monitoreo del rendimiento de nuestro sitio, para esto se hizo uso de la herramienta New Relic, la misma ya estaba disponible para su uso en nuestra infraestructura gracias a nuestro proveedor (Pantheon).
New relic es una herramienta de monitoreo avanzada, con la cual podemos obtener una muy buena perspectiva del estado de nuestro sitio. El sistema recaba información del día a día, segundo a segundo. Nos permite monitorear los tiempos de ejecución de cada transacción ejecutada en el sitio, porcentaje de error, tiempos de consumo por herramienta del stack (PHP, MYSQL, Redis, entre otros), cantidad de requests por minuto y muchos otros indicadores de relevancia.
Durante los primeros días del monitoreo vimos unos números bastante preocupantes, teníamos transacciones que incluso consumían más de 1000ms, por lo que a partir de este punto decidimos empezar a atacar el problema pero dividiéndolo por herramienta del stack como se explicará seguidamente.
Versión de PHP, algo que no esperamos tuviera tanto peso.
Como podemos observar en la gráfica de rendimiento, PHP estaba consumiendo más de 500 ms de los 750 ms que tomaba cada request, aproximadamente un 66% del total de la transacción y aquí fue donde empezamos nuestro análisis de la situación.
En nuestra primera revisión del proyecto nos topamos que uno de los motivos por los que PHP estaba consumiendo tanto tiempo era debido a una versión antigua del lenguaje, el sitio estaba en la versión 5.6 de PHP y en el momento ya estaba la versión 7 que venía con varias mejoras en su rendimiento por lo que procedimos a realizar el cambio de versión.
Esto implicó hacer una revisión total del código del sitio, ya que como mencionamos anteriormente hay gran cantidad de funcionalidad custom y el cambio de versión implicaba que ya algunas funciones utilizadas estaban obsoletas por lo que necesitábamos actualizar el código viejo para que cumpliera con la nueva versión del lenguaje.
MYSQL, “cachear “ las cosas siempre es mejor.
Como es bien sabido MYSQL ya provee su propia capa de caché, pero muchas veces no es suficiente para subsanar todas las necesidades de una aplicación altamente demandante, por lo cual nos plantemos el objetivo de hacer mejor uso de los recursos que esta aplicación estaba utilizando a partir del uso de una capa extra de caché.
Como mencionamos, nuestro siguiente objetivo fue bajar los tiempos que estaba consumiendo MYSQL. Cuando hablamos de rendimiento es sabido que las operaciones que consumen más tiempo de ejecución son aquellas que necesitan ir al disco duro a traer información para ser procesada y servida al usuario, MYSQL hace un uso intensivo del disco ya que cada vez que el usuario realiza alguna consulta o petición de alguna página que necesita la carga de información en la base datos esto implica realizar una lectura en el disco duro.
MYSQL estaba consumiendo alrededor de unos 200 ms del tiempo de carga del sitio lo que representaba el 26% del tiempo total, por lo que era imperativo tratar de optimizar también estos tiempos. Luego de investigar un poco vimos que la mejor opción era colocar una capa extra de caché.
Nuestra mejor opción fue Redis, un backend caché que mantiene los registros de caché siempre cargados en la memoria RAM, asegurándonos una gran velocidad a la hora de servir los datos. Durante el proceso de configuración dejamos a cargo a Redis de administrar el caché para operaciones demandantes como consultas de vistas, información requerida para el desligue de nodos, entre muchos otros.
Primeros resultados.
Estos fueron los primeros 2 grandes cambios que aplicamos para poder optimizar nuestro sitio: actualizar PHP a su última versión e implementar el caché backend Redis.
Resultados de implementación de Redis.
El 27 de Noviembre del 2017 sacamos a producción el primero de estos cambios: el cache backend (Redis), esto nos dio resultados inmediatos que pudimos apreciar gracias a New Relic. A continuación veremos las gráficas de rendimiento desde el día 24 de Noviembre al 29 de Noviembre.
En la gráfica anterior se representan el tiempo total de la transacción (linea azul en la parte superior) y el tiempo que MYSQL consume de esa transacción (gráfica de color amarillo). Como podemos apreciar, el día 27 de Noviembre hubo una gran variación en el tiempo que MYSQL consumía por transacción, se logró bajar de los 160 ms a los 50 ms por transacción, dándonos una mejora aproximada del 68,75% en los tiempos de consumo de MYSQL.
Debemos destacar que la implementación de Redis afectó también los tiempos de PHP, dado que Redis tiene en su caché gran cantidad de información ya procesada, PHP obtuvo un descanso al no tener que procesar una y otra vez la misma información. La mejora que implicó Redis sobre el PHP fue de al rededor de los 110 ms menos en su tiempo de ejecución.
En resumen la optimización lograda sobre el tiempo total del request tras la implementación Redis fue de aproximadamente un 29,33% . Pasamos de unos 750 ms a unos de 530 ms por request.
Solo como dato curioso adjuntamos la siguiente gráfica en la cual se muestra el tiempo que está consumiendo Redis.
Como se puede observar, a Redis le toma menos de 3 ms en hacer lo que a MYSQL le tomaba 110 ms, sin duda alguna, una gran mejora.
Resultados de actualización de PHP.
Cuando iniciamos este proceso de análisis y optimización nunca pensamos que el solo hecho de cambiar de una versión a otra del lenguaje nos fuera a generar tanta ganancia a nivel de rendimiento del sistema. Sacamos el cambio de versión de PHP a producción el día 1 de diciembre del 2017 y al igual que Redis, significó un cambio inmediato y muy significativo en el rendimiento del sitio.
Como podemos observar antes del cambio de versión del lenguaje, PHP estaba utilizando al rededor de unos 510 ms por request y luego de la salida a producción del cambio de versión, este consumo pasó a unos 255 ms por request lo que significa una mejora en los tiempos de consumo de PHP del 50%.
Este cambio de versión de PHP también afectó de alguna manera los tiempos de consumo del MYSQL, probablemente debido a mejoras en el módulo de conexión a la base de datos. MYSQL pasó de consumir aproximadamente unos 50 ms a unos 35ms por request.
Esta optimización nos deja con los siguientes números: pasamos de un tiempo total de request (posterior a la implementación de Redis) de unos 575 ms a unos 310 ms, lo que nos deja una reducción aproximada del 46,08% en los tiempo de ejecución del request.
Resultados finales de la primera fase de optimización.
Como pudimos observar, en cada una de las optimizaciones obtuvimos mejoras impresionantes con cambios sumamente simples pero con sentido, que fueron posibles gracias a un análisis e investigación sobre posibles herramientas o técnicas que nos permitieran mejorar el rendimiento del sito.
Hasta ese punto ya el rendimiento se había mejorado aproximadamente un 241,93% ((750ms ÷ 310ms) * 100), lo cual fue un gran logro y con el cual nos sentimos muy satisfechos.
Pero el plantearnos la meta de mejorar rendimiento no fue solo porque queríamos tener buenos números en nuestros índices por request, se hizo para mejorar también el indice de satisfacción del usuario, el cual era algo alarmante en el sitio.
Pero, ¿Cómo medimos el índice de satisfacción del usuario? Con este propósito se creó el Apdex (Application Performance Index), un estándar abierto que define una forma estandarizada para medir el rendimiento de una aplicación.
La medición de este índice también está disponible en New Relic, por defecto el tiempo ideal es de 0.5 segundos por request, este valor es configurable, pero para tratar de dar al cliente la mejor experiencia posible nosotros lo mantenemos en el tiempo ideal ya antes mencionado.
El apdex nos indica cuando uno de nuestros request es Satisfactorio, Tolerable o Frustrante basado en la siguiente premisa:
T = 0.5 segundos.
- Satisfactorio: El tiempo del request <= T (0.5 segundos)
- Tolerable: El tiempo del request es >T y <= 4T (Entre 0.5 y 2 segundos)
- Frustrante: El tiempo del request >4T (Mayor que 2 segundos)
Y basándose en la cantidad de requests Satisfactorios, Tolerables y el total de request durante el periodo de tiempo de recaudación de datos se obtiene el apdex de nuestro sitio en ese momento dado. El rango del apdex es de entre 1 y 0, donde 1 es el mejor estado y 0 es el peor estado. Si desean más información sobre cómo se calcula pueden ir a este link.
Ya entrando en materia, el apdex del sitio antes de iniciar el proceso de mejora del rendimiento era de un 0.62 en promedio, lo que significa un nivel de satisfacción del usuario bastante pobre y para ejemplificarlo tomamos los datos del 29 de Julio al 01 de agosto de 2017 donde hubo un total de 108503 requests de los cuales:
- Solo el 20% fueron satisfactorios (22105 request)
- El 79% fueron Tolerables (85742 request)
- Y el 1% fueron frustrantes (657 request)
¿Esto qué nos decía? Que el sitio en este caso estaba funcionado pero a marchas forzadas, los usuarios estaban experimentando un sentimiento de lentitud en la carga del sitio en general, lo cual claramente afecta la satisfacción de un usuario al hacer uso de una aplicación web.
Posterior a la optimización pudimos darle vuelta a esos números sustancialmente, a continuación la gráfica del apdex desde el 10 de Noviembre de 2017 hasta el 3 de Enero de 2018.
Como se pude ver claramente en la gráfica, el índice subió drásticamente, lo cual se puede corroborar con los datos de entre el 22 y el 25 de Diciembre del 2017 donde se registraron 144366 request, de los cuales:
- El 75,48% fueron satisfactorios(108969 request)
- El 24,46% tolerable (35314 request)
- El 0,057% frustrante (83 request)
Con lo que podemos afirmar que además de mejorar el rendimiento a nivel técnico, dimos una mejora sustancial en el nivel de satisfacción de los usuarios del sitio.
Segunda etapa: Mejora del código y eliminación de malas practicas de desarrollo.
Ya en la primera etapa de mejora habíamos obtenido grandes resultados, pero aún nos restaba mejorar el código desarrollado durante la primera fase del proyecto ya que, como se ha mencionado con anterioridad, se implementaron diversas funcionalidades utilizando técnicas de desarrollo no óptimas.
Para identificar estas malas prácticas también utilizamos New Relic: basándonos en la información de tiempo de consumo por transacción se identificaron varias peticiones que estaban consumiendo mucho del tiempo del request.
Lastimosamente no podemos mostrar las transacciones especificas y sus tiempos por que este artículo se escribió ya bastante tiempo después de la implementación de estos cambios y New Relic conserva el histórico de peticiones por un tiempo limitado, pero sí podemos hablar de los cambios implementados a grosso modo.
Views PHP.
Durante el proceso de análisis de datos que nos daba New Relic confirmamos lo que ya sospechábamos: las transacciones que incluían views estaban tardando más de lo que deberían. Todo se debía a la implementación de un módulo llamado Views PHP, que básicamente lo que permite es hacer uso de código PHP en la configuración de cada view, por ejemplo, se podía utilizar para reescribir la salida de un campo y hacer algo más personalizado usando el código PHP directamente. Pero eso fue un gran pecado, porque hacer uso de algo como esto implica que, si se carga una página con un view con este tipo de implementación, el sistema va a tener que interpretar el código PHP, posteriormente ejecutar las consultas necesarias para cargar el view y de nueva cuenta volver a a interpretar el código PHP existente en la configuración del view cargado, lo que claramente es un desperdicio de recursos.
Para solucionar el daño causado por estas malas implementaciones de funcionalidades en estos views se tuvo que realizar todo un inventario de todos aquellos views que tenían PHP en su configuración, posteriormente se realizó un análisis de cada funcionalidad implementada para posteriormente desarrollar los views plugins para remplazar esas funcionalidades en configuración y de una vez por todas dejarlas plasmadas en código base del sitio.
Eliminación de código no utilizado.
Como parte del proceso de mejora también se logró identificar que teníamos gran cantidad de código que ya no estaba siendo utilizado debido a que varias de las secciones o procedimientos que hacían uso de estos fragmentos de código fueron eliminados ya tiempo atrás, por lo que se decidió eliminar todo aquel código viejo que ya no estuviera en uso con el propósito de agilizar el tiempo de carga total del sitio y además hacer más comprensible para nosotros como desarrolladores el código custom existente en el proyecto.
PHP filter.
Lastimosamente durante este proceso de análisis y mejora también encontramos la implementación de otro módulo con una funcionalidad muy parecida al de Views PHP: PHP filter que permite interpretar código PHP en los campos de texto largo de drupal haciendo uso de un filtro de texto específico para este propósito. Esto tenía el mismo impacto que el caso de views, ya que se debe interpretar de nueva cuenta el PHP.
PHP filter se utilizó ampliamente en el sitio para crear campos personalizados para el módulo Display suite y en muchos tipos de contenido, lo que nos estaba restando mucho en rendimiento.
Para solucionarlo se tuvo que, al igual que en el caso de views, hacer un inventario de los campos que utilizaban este Filtro de texto y analizar la mejor solución para cada caso.
La solución para la gran mayoría de los casos fue crear pseudocampos y templates personalizados para poder migrar todas esas configuraciones al código base del sitio.
Números finales.
Como resultado de las mejoras mencionadas con anterioridad se generó el siguiente impacto a nivel del repositorio de código:
- Se eliminaron más de 71000 lineas de código.
- Se agregaron más de 31000 lineas nuevas de código.
- Se hicieron muchos commits, no estamos seguros de cuantos dado que github solo nos dice:"This pull request is big! We’re only showing the most recent 250 commits."
El esfuerzo por parte del equipo fue enorme y eso se notó con los números finales de las estadísticas de rendimiento.
Como se puede observar logramos una mejoría notoria en el rendimiento del sitio después del ultimo deployment y, como era de esperarse, el mayor porcentaje de mejora se lo llevó PHP: se bajó el consumo de PHP un 50%, pasó de 300ms a 150ms. La reducción en los tiempos por request fue de un 57,14%, se pasó de 350ms a 200ms.
Gracias a esta última mejora, logramos llevar el sitio a un punto de estabilidad y velocidad que, si al principio nos lo hubieran planteado, lo hubiéramos creído casi imposible, pero gracias a la utilización de las herramientas correctas, el análisis, trabajo en equipo y el esfuerzo de cada persona involucrada en el proyecto, se logró dar este gran resultado. El resultado final es una optimización del 350% en los tiempos por request ya que pasamos de unos 750ms por transacción a unos 200ms por transacción.
