in web we trust

Cuando tienes una aplicación en producción es más que necesario controlar los tiempos de las peticiones más lentas.

Sin embargo muchas veces con el log de Rails no es suficiente, y hay que alcanzar un mayor nivel de detalle.

El log en modo debug nos da todo el detalle que necesitamos, pero mostrando demasiada información (¿de qué nos sirve saber que un SELECT sencillo tarda 0.001 segundos?).

Pero si en ese log pudiéramos filtrar las consultas SQL más lentas sí que tendríamos información de consultas lentas asociadas a cada petición al servidor.

Gracias al plugin query trace y a una pequeña modificación podemos mostrar qué consultas tardan más de 1 segundo:

 module ActiveRecord
   module ConnectionAdapters
     class AbstractAdapter
       def log_info(sql, name, runtime)
         return unless @logger
         @logger.info(
           format_log_entry(
             "#{name.nil? ? "SQL" : name} (#{sprintf("%f", runtime)})",
             sql.gsub(/ +/, " ")
           )
         ) if (RAILS_ENV == 'production' && runtime > 1.0) || RAILS_ENV != 'production'
       end
     end
   end
 end
 

Este código lo he probado en Rails 1.2.x, no sé si funcionará en otras versiones.