Profiling de peticiones en ruby on rails

Ruby es un lenguaje dinámico muy potente pero por ello también muy díficil de depurar en ocasiones. En ruby on rails con los named_scope, before_filter, plugins, gems, etc puede ser todavía peor.

Sin embargo, en los sistemas operativos que soportan DTrace tenemos una ayuda para encontrar los cuellos de botella de la aplicación, por ejemplo, usando el script que hay en: http://dl.getdropbox.com/u/478290/blog/dtrace/rb_linetime.d.

Simulo un before_filter muy lento que se ejecute para todas las request como éste:

22  def takes_too_long
23    i = 0
24    100.times{
25      100000.times{i+=1}
26      100000.times{i-=1}
27    }
28  end

Después arrancamos el servidor de ruby on rails y obtenemos su PID (vía passenger-status, ps, top...)

Ejecutamos:

sudo dtrace -s rb_linetime.d -p pid_del_servidor > request.log

Hacemos una petición a la aplicación ruby on rails, después paramos DTrace con Ctrl+C y en request.log podemos ver los ficheros ruby que se van cargando y cuanto tarda cada uno, en concreto, nos fijamos en las líneas:

FILE                                                                                                                      LINE  COUNT    AVG(us)      SUM(us)
...

/Users/javiyu/projects/rails/prueba/vendor/rails/activesupport/lib/active_support/core_ext/module/introspection.rb          86    849        188       160330
/System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.4/lib/mongrel/configurator 285     83      30374      2521066
/Users/javiyu/projects/rails/prueba/app/controllers/application.rb 26 600000         16      9690835
/Users/javiyu/projects/rails/prueba/app/controllers/application.rb   25 681051         16     11087871
/Users/javiyu/projects/rails/prueba/vendor/rails/railties/lib/commands/servers/base.rb 14     69     974199     67219750
....

Vemos que application.rb tarda mucho más de lo normal, e incluso detecta el número de línea en el que está el cuello de botella, en este caso la 25 y la 26.