#249 Notifications in Rails 3

A continuación se muestra una captura de pantalla de una pequeña aplicación Rails que muestra un listado de productos que se pueden ser ordenar y paginar. Queremos saber lo que tarda cada petición en cargar para ver cómo de eficiente es la aplicación y guardar estq información en la base de datos para así poder calcular métricas de rendimiento.

Podemos recopilar esta información de varias maneras. Una solución sería analizar el fichero de trazas de la aplicación y extraer de ahí la información que buscamos, pero si lo que queremos hacer es calcular tiempos medios de carga de cada página u otras estadísticas similares será más sencillo guardar estos datos en la base de datos . También podríamos utilizar, por supuesto, una herramienta como RPM de NewRelic, pero en este caso queremos algo muy sencillo que simplemente almacene el tiempo empleado en cada petición.

Notificaciones

Implementaremos esto mediante el uso de una nueva funcionalidad de Rails 3: ActiveSupport::Notifications. Estas notificaciones se pueden usar para crear nuestros propios instrumentos, que reciben un bloque de código y cuando este bloque termine su ejecución enviará un evento que activará a toda notificación que esté suscrita a él. Una aplicación Rails 3, durante una petición típica, envía varias notificaciones a las que podemos suscribirnos. Antes de escribir nuestro propio instrumental vamos a intentar suscribirnos a uno de estos eventos ya existentes para ver cómo funcionan.

Lo primero que hay que hacer es crear un nuevo fichero en el directorio config/initializers de nuestra aplicación en el que escribiremos el código necesario para suscribirnos a la notificación, invocando a ActiveSupport::Notification.subscribe. Si se le pasa un argumento a este método podemos filtrar a qué notificaciones nos queremos suscribir, pero esto no nos interesa ahora porque queremos ver todas las notificaciones que nuestra aplicación envía durante la petición. El método también recibe un bloque con cinco argumentos: name es el nombre de la notificación, start y finish indican un tiempo de inicio, payload contiene un diccionario con información sobre la notificación y por último id es el identificador. Mostremos esta información.

ActiveSupport::Notifications.subscribe do |name, start, finish, id, payload|
  Rails.logger.debug(["notification:", name, start, finish, id, payload].join(" "))
end

Si arrancamos el servidor Rails y volvemos a cargar la página principal de la aplicación veremos las notificaciones que se han hecho durante esta petición. Esta es la primera:

notification: start_processing.action_controller 2011-01-19 21:51:40 +0000 2011-01-19 21:51:40 +0000 bac10ab8b439502ce5ba {:controller=>"ProductsController", :action=>"index", :params=>{"controller"=>"products", "action"=>"index"}, :formats=>[:html], :method=>"GET", :path=>"/products"}

En la traza de la notificación anterior podemos ver qué parámetros se le han pasado: el nombre, los tiempos de inicio y de fin, el identificador de la notificación y por último el diccionario payload. Estas son todas las notificaciones que se ejecutaron durante la petición:

start_processing.action_controller
notification: sql.active_record
notification: sql.active_record
notification: sql.active_record
notification: !render_template.action_view
notification: !render_template.action_view
notification: render_template.action_view
notification: process_action.action_controller

Las notificaciones anteriores parece que incluyen las consultas de ActiveRecord, por lo que podríamos suscribirnos a ellas para ver cuánto tiempo tarda cada consulta a la base dedatos, pero nosotros nos vamos a centrar en la última porque es la que se activa cuando la petición ha terminado y por tanto es la que podemos usar para determinar el tiempo total de procesamiento de la petición.

notification: process_action.action_controller 2011-01-19 21:51:40 +0000 2011-01-19 21:51:41 +0000 bac10ab8b439502ce5ba {:controller=>"ProductsController", :action=>"index", :params=>{"controller"=>"products", "action"=>"index"}, :formats=>[:html], :method=>"GET", :path=>"/products", :status=>200, :view_runtime=>208.36210250854492, :db_runtime=>80.30999999999999}

La notificación trae además otros datos interesantes como params, path, status, view_runtime y db_runtime. Más adelante usaremos alguno de estos.

Queremos guardar esta información en la base de datos para poder averiguar cuáles son las páginas que van más lentas. Si estuviéramos con una aplicación de producción sería recomendable, por motivos de eficiencia, usar un almacenamiento basado en memoria pero en nuestro caso nos bastará con guardar estos datos en un modelo normal.

Tenemos los Nifty Generators de Ryan Bates instalados en nuestra aplicación, por lo que usaremos el generador nifty:scaffold para crear este modelo, así como su controlador y sus vistas. El modelo tendrá un campo path para guardar la URL y tres campos de duración para guardar el tiempo empleado en las diferentes partes que componen una petición.

$ rails g nifty:scaffold page_request rails g nifty:scaffold page_request path:string page_duration:float view_duration:float db_duration:float index

Tras esto ejecutaremos la migración para crear la nueva tabla.

$ rake db:migrate

Ya tenemos un modelo en el que podemos almacenar la información que recuperemos acerca de cada petición. Tendremos que tener en cuenta el nombre de la notificación (process_action.action_controller) para suscribirnos sólo a dicha notificación. También tendremos que anotar los nombres de los campos de payload de los que queremos extraer información.

De vuelta en nuestra archivo notifications.rb pasaremos un argumento a la llamada a ActiveSupport::Notifications.support para filtrar a qué notificaciones nos queremos suscribir. Una forma de hacerlo es pasando una expresión regular: por ejemplo, para suscribirnos a todas las notificaciones que contienen action_controller en su nombre podemos ejecutar lo siguiente:

ActiveSupport::Notifications.subscribe /action_controller/ do |name, start, finish, id, payload|
  Rails.logger.debug(["notification:", name, start, finish, id, payload].join(" "))
end

Alternativamente podemos pasar una cadena para dejar pasar una única notificación, que es lo que haremos. En lugar de sólo trazar los datos de la notificación los usaremos para construir una nueva instancia de PageRequest que guardaremos en la base de datos.

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, start, finish, id, payload|
  PageRequest.create! do |page_request|
    page_request.path = payload[:path]
    page_request.page_duration = (finish - start) * 1000
    page_request.view_duration = payload[:view_runtime]
    page_request.db_duration = payload[:db_runtime]
  end
end

Si ahora reiniciamos nuestro servidor Rails, visitamos unas cuantas páginas y luego cargamos /page_request podemos ver el listado de peticiones que hemos hecho así como la duración de cada una, que han sido almacenadas en la base de datos. Podemos usar esta información para averiguar cuáles son las páginas más lentas, trazar gráficas de rendimiento a lo largo del tiempo, etc.

Creación de notificaciones

Los eventos que Rails envía internamente se utilizan por lo general para recopilar métricas, como en el caso anterior. Pero también podemos usar las notificaciones para cualquier otro propósito, y para ver cómo se hace crearemos un instrumento en nuestra aplicación de tienda.

Nuestra aplicación permite que los usuarios busquen productos, y queremos guardar los términos de búsqueda que se van introduciendo. En nuestro modelo Product tenemos una método de clase search que es donde tiene lugar la busqueda propiamente dicha y que es el sitio ideal para guardar los términos de búsqueda. No queremos recargar nuestro modelo con la tarea de guardar los términos de búsqueda en una tabla de la base de datos por lo que en su lugar desde esta clase lanzaremos una notificación que contiene la información de esta búsqueda, y a la que nos podemos suscribir en cualquier punto del código de nuestra aplicación.

Para crear la notificación tenemos que crear primero una nueva instrumentación, lo que se hace invocando a ActiveSupport::Notifications.instrument, que recibe dos argumentos: el primero es el nombre que le queremos dar a la notificación y el segundo cualquier cosa que queramos que se pase por payload. El segundo argumento por lo general es un hash de parámetros, en nuestro caso el término de búsqueda.

class Product < ActiveRecord::Base
  def self.search(search)
    if search
      ActiveSupport::Notifications.instrument("products.search", :search => search)
      where('name LIKE ?', "%#{search}%")
    else
      scoped
    end
  end
end

Si instrument recibe un bloque los tiempos de inicio y fin que marque la notificación serán los tiempos en los que se inició y terminó la ejecución del bloque. Como estamos usando ámbitos esta información no resulta muy útil, porque la consulta a base de datos no tiene lugar en el método search, por tanto los omitiremos y los tiempos de inicio y fin serán el mismo.

En el fichero de inicialización de nuestras notificaciones podemos suscribirnos a nuestra nueva notificación y gestionarla como queramos. Por ejemplo, nos limitaremos a trazar el término de búsqueda.

ActiveSupport::Notifications.subscribe "products.search"  do |name, start, finish, id, payload|
  Rails.logger.debug "SEARCH: #{payload[:search]}"
end

Nos suscribimos a nuestra propia notificación de la misma manera que lo haríamos con las notificaciones incorporadas en Rails, y podemos recuperar el término de búsqueda del hash de payload y trazarlo. Si reiniciamos el servidor y buscamos “milk” veremos que se traza el término de búsqueda.

SEARCH: milk

Por supuesto podríamos crear una tabla en la base de datos para guardar esta información igual que hicimos con las métricas que recopilamos anteriormente.

Así es como podemos utilizar las notificaciones en Rails 3 para sacar lógica de una clase y gestionarla en otro sitio. Los suscriptores de una notificación pueden estar en diferentes sitios, y podemos tener todos los suscriptores que queramos. Tan sólo tenemos que tener cuidado con el patrón de notificación porque es fácil abusar de él. Por ejemplo, supongamos que tenemos un modelo User en nuestra aplicación y queremos enviar un correo cuando se registra un nuevo usuario. En este escenario podríamos utilizar las notificaciones pero no sería un buen uso, lo mejor es limitarnos a utilizar las notificaciones para trazas y otro código que no forma parte del núcleo de la aplicación ya que corremos el riesgo de desperdigar la lógica de nuestra aplicación por sitios dispares lo que complicaría el código de la aplicación: cualquiera puede estar escuchando la notificación desde cualquier sitio.

Con esto cerramos este episodio. Se puede encontrar más información sobre las notificaciones en Rails en la documentación oficial.