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.

Obtención de información relativa al procesador

Para la generación de código optimizado puede ser necesario conocer sobre que tipo de procesador se está ejecutando nuestro programa y que instrucciones soporta.

La instrucción cpuid proporciona información relativa al procesador.
Por ejemplo.

#include <stdio.h>

typedef unsigned int uint;

void print_register_str(reg){
 int i;
 
 for(i=0; i<4; i++){
  printf("%c", reg >> (i*8) );
 } 
}

void cpuid(uint *eax, uint *ebx, uint *ecx, uint *edx, uint service){
 __asm__ (
  "pushl %%ebx \n\t"
  "cpuid \n\t"
  "movl %%ebx, %1 \n\t"
  "popl %%ebx \n\t"
  : "=a" (*eax),
  "=S" (*ebx),
  "=c" (*ecx),
  "=d" (*edx)
  :"a" (service)
 );
}

int main(){
 uint eax, ebx, ecx, edx;
 
 printf("VendorString: ");
 cpuid(&eax, &ebx, &ecx, &edx, 0);
 print_register_str(ebx);
 print_register_str(edx);
 print_register_str(ecx);
 printf("\n");

 
 cpuid(&eax, &ebx, &ecx, &edx, 1);
 printf("MMX support: %d\n", (edx >> 23) & 1); 
 printf("SSE support: %d\n", (edx >> 25) & 1);
 printf("SSE2 support: %d\n", (edx >> 26) & 1);
 printf("HyperTransport: %d\n", (edx >> 28) & 1);
 printf("SSE3 support: %d\n", (ecx) & 1);

 return 0;
}

Este programa tiene como resultado para mi cpu.

VendorString: GenuineIntel
MMX support: 1
SSE support: 1
SSE2 support: 1
HyperTransport: 1
SSE3 support: 1

Se puede obtener más información específica, aquí vienen algunos ejemplos más: http://softpixel.com/~cwright/programming/simd/cpuid.php.