#368 MiniProfiler

Supongamos que estamos trabajando en una aplicación Rails y empezamos a notar que va un poco lenta. Obviamente queremos optimizar su rendimiento pero antes de hacerlo es mejor utilizar una herramienta de perfilado de forma que podamos averiguar dónde están los cuellos de botella. Hay disponibles muchas herramientas de este tipo, pero en este episodio vamos a usar MiniProfiler, que fue creada originalmente para el desarrollo en .Net pero que ha sido traducida a Ruby y viene muy bien para perfilar aplicaciones Rails. Se puede incluir fácilmente MiniProfiler a una aplicación Rails, lo único que hay que hacer es añadir la gema al Gemfile para instalarla.

gem 'rack-mini-profiler'

Tras reiniciar la aplicación y cargar una de sus páginas veremos que MiniProfiler está habilitado por defecto en modo de desarrollo. Se muestra en la parte superior el tiempo que ha tardado la página en cargar, y haciendo clic en este tiempo iremos a un desglose detallado del tiempo empleado en cada parte de nuestra aplicación.

Aquí puede verse el tiempo empleado en el controlador y donde más tiempo hemos tardado ha sido en la ejecución de la salida de la acción index , supuestamente porque tiene que ejecutar 5 consultas SQL (debido a la carga perezosa de objetos de la base de datos, este tiempo ocurre durante la interpretación de la plantilla). Si hacemos clic en el enlace SQL veremos exactamente qué consultas SQL se ejecutaron, así como una traza de cada una de ellas.

Esta traza muestra que se realiza una consulta SELECT para recuperar todos los contenidos de cada tarea de cada proyecto. En la propia página sólo mostramos el número de tareas que tiene cada proyecto por lo que estamos consultando muchos más datos de los que realmente necesitamos. Si miramos la plantilla que hemos ejecutado veremos el código que muestra el número de tareas.

<%= pluralize project.tasks.length, "task" %>

No es eficiente llamar a project.tasks.length para obtener el número de tareas porque la consulta recuperará todos los datos de todas las tareas de la base de datos, por lo que usaremos tasks.size.

<%= pluralize project.tasks.size, "task" %>

Veremos que al recargar la página MiniProfiler muestra un número más pequeño porque la base de datos tiene que enviar un número menor de datos. En lugar de obtener todos los datos relacionados con un proyecto sólo estamos recuperando el recuento, lo que lleva menos tiempo. Dicho esto todavía estamos ejecutando cinco consultas SQL en esta página, y según vayamos añadiendo productos veremos que este número va aumentando. Hay una forma de reducir el número de consultas a una pero tendremos que escribir SQL directamente. Lo invocaremos en la acción index de ProjectsController, si bien en una aplicación para producción este método tendría que ir alojado en el modelo.

def index
  @projects = Project.order(:created_at).select("projects.*, count(tasks.id) as tasks_count").joins("left outer join tasks on project_id = projects.id").group("projects.id")
end

Tenemos que recuperar algo más que las columnas de la tabla de proyectos, también recuperamos la cuenta del número de tareas. Hemos llamado tasks_count a esta columna, y es importante tener en cuenta este nombre porque es lo que utilizará tasks.size en lugar de ejecutar una segunda consulta. Tenemos que unir el resultado con la asociación tasks pero si usamos joins(:tasks) no sería la mejor manera de hacerlo porque realizará un join interno y por tanto dejará de lado los proyectos que no tengan tareas. Hemos escrito un fragmento de SQL que realizará la combinación de tabla izquierda, no se trata de la consulta más elegante pero la página carga mucho más rápido, y MiniProfiler muestra que sólo estamos ejecutando una consulta SQL.

Ahora la consulta SQL tarda un milisegundo en ejecutarse, pero veremos que a ActiveRecord le lleva cierto tiempo instanciar los objetos. MiniProfiler proporciona un método para ver el tiempo que tarda en ejecutarse un fragmento concreto de código, que podemos usar en el controlador. Podemos invocar a Rack::MiniProfiler.step pasándole un bloque y una descripción, de forma que en el informe aparecerá el tiempo que ha tardado el bloque en ejecutarse. Como los proyectos se cargan de forma diferida en la vista, tenemos que invocar aquí @project.all para cargarlos antes.

def index
  @projects = Project.order(:created_at).select("projects.*, count(tasks.id) as tasks_count").joins("left outer join tasks on project_id = projects.id").group("projects.id")
  Rack::MiniProfiler.step("fetch projects") do
     @projects.all
  end
end

Podemos ver el tiempo que lleva cargar todos los proyectos recargando la página.

Este enfoque es útil siempre que nos encontremos con que tenemos que medir algo muy concreto. El siguiente paso en la optimización de esta consulta sería añadir una columna con el valor del contador, lo que no haremos aquí, ya que se vió en el episodio 23.

Ejecución en modo de producción

Hasta ahora hemos estado realizando el perfilado en el entorno de desarrollo, que siempre funciona más lento que el modo de producción. Cuando tengamos que hacer un perfilado intensivo de una aplicación es mejor hacerlo en producción y esto puede ser un poco complicado en una máquina de desarrollo si bien veremos aquí los pasos a seguir. Primero tenemos que cambiar la opción serve_static_assets en nuestro fichero de configuración de producción para que sea true.

# Disable Rails's static asset server (Apache or nginx will already do this)
config.serve_static_assets = true

Alternativamente podemos configurar un entorno de preproducción separado como hicimos en el episodio 72. Luego tenemos que generar los estáticos de nuestra aplicación y configurar la base de datos en el entorno de producción. Tras esto ya podemos arrancar el servidor en producción.

$ rake assets:precompile
$ rake db:setup RAILS_ENV=production
$ rails s -e production

Si ahora recargamos la página veremos que la aplicación funciona en modo de producción. El tiempo que muestra MiniProfiler ya no aparece porque en producción la funcionalidad está desactivada. Conseguir que aparezca es fácil, simplemente añadiendo un before_filter en ApplicationController.

class ApplicationController < ActionController::Base
  protect_from_forgery
  
  before_filter :miniprofiler
  
  private
  def miniprofiler
    Rack::MiniProfiler.authorize_request
  end
end

Un efecto útil de este enfoque es que nos permite cambiar el comportamiento según el usuario actual, de forma que podríamos hacer que el perfilador sólo apareciese cuando el usuario fuese administrador.

Cuando estamos en modo de producción tendremos que reiniciar el servidor cada vez que hagamos un cambio en el código de la aplicación. Tras recargar la página veremos que el perfilador vuelve a aparecer. Al desplegar la aplicación en las máquinas de producción veremos que los resultados serán diferentes porque posiblemente el hardware sobre el que se ejecute la aplicación será mucho más potente que la máquina en la que estamos desarrollando la aplicación. Por tanto, en el equipo de desarrollo es mejor centrarse en el tiempo que podemos reducir en la carga de la página que fijarse en un valor absoluto. Si podemos mejorar el tiempo de carga de una página en desarrollo es batante probable que también mejore el tiempo de carga en el entorno de producción.

Más funcionalidades

Vamos a terminar este episodio con un repaso de otras de las funcionalidades de MiniProfiler. Una de las más útiles es la manera en la que gestiona las redirecciones. Si editamos un producto y luego hacemos clic en “update” veremos dos valores del perfilador, uno para la acción de actualización y otro para la de visualización. Esto quiere decir que podemos ver los valores de perfilado de acciones que terminen con una redirección. Otra funcionalidad muy útil es la posibilidad de personalizar MiniProfiler enviando un parámetro especial en la URL de la petición. Si añadimos el parámetro pp=help veremos la lista de opciones que podemos usar.

Append the following to your query string:

  pp=help : display this screen
  pp=env : display the rack environment
  pp=skip : skip mini profiler for this request
  pp=no-backtrace : don't collect stack traces from all the SQL executed
  pp=full-backtrace : enable full backtrace for SQL executed
  pp=sample : sample stack traces and return a report isolating heavy usage (requires the stacktrace gem)

Tenemos opciones para ver variables de entorno de Rack, configurar el volcado de las peticiones SQL, y una opción llamada sample que devuelve la pila de llamadas. Sam Safron ha escrito una anotación en su blog donde explica todas estas opciones de la gema, entrando en detalle sobre el perfilado de consultas ActiveRecord, así como otras funcionalidades interesantes como especificar el método que queremos perfilar para añadirlo a la lista de resultados. También merece la pena leerse el README de la gema que contiene información de otras cosas como el motor de almacenamiento, que por defecto es en un archivo pero podemos usar Redis, lo que es útil si tenemos varios servidores ejecutando nuestra aplicación.