¿Cómo registro cada método que se llama en un programa de Ruby?

Question

Heredé una gran pila de código de Ruby que, francamente, es casi imposible de entender para un mortal como yo. En realidad, es un código de prueba de la unidad Rspec, pero la estructura es "altamente inusual" para decirlo de forma agradable.

Lo que me gustaría ser capaz de hacer es ejecutar el código, y tienen la siguiente información registrada en alguna parte:

• todos los métodos que se invoca, incluyendo el nombre de la clase que define el método, y el nombre del archivo donde se ha definido el método invocado (sí, tenemos la misma clase/método definido en múltiples archivos diferentes, y es difícil saber cuál se está invocando)
• (opcionalmente) los parámetros pasados ​​a cada método invocado

Con eso, podría comenzar a tratar de refactorizarlo. Sin él, será una tarea muy difícil resolverlo, debido al tamaño de la base de código (20k + casos de prueba de la unidad).

No puedo permitirme realizar ediciones al por mayor del código que se está ejecutando, porque se rompe cuando incluso se utiliza un lenguaje hostil (es decir, con frecuencia). En cambio, necesito poder instrumentar el código en su estado actual, o con cambios mínimos a lo que existe ahora.

¿Hay alguna forma de registrar este nivel de detalle sin realizar cambios al por mayor en la base de códigos? He echado un vistazo al perfilador de Ruby para ver si podría ayudar, y probablemente podría; Tengo curiosidad por saber si hay una manera mejor (especialmente registrar el nombre de archivo que contiene el método invocado).

Gracias de antemano

Answer 1

Esto es definitivamente posible - de hecho, hay incluso un método para ello! Sólo tiene que añadir esto en alguna parte en el código antes del punto en que desea iniciar cosas de registro:

set_trace_func proc { |event, file, line, id, binding, classname| 
    printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname 
} 

El ingrediente secreto que deseas proviene de Kernel#set_trace_func, como se señaló anteriormente:

• set_trace_func (proc) => proc
• set_trace_func (nil) => nil

Establece proc como el controlador para el seguimiento o desactiva el rastreo si el parámetro es nil. proc toma hasta seis parámetros: un nombre de evento, un nombre de archivo, un número de línea, un identificador de objeto, un enlace y el nombre de una clase. proc se invoca cada vez que ocurre un evento. Los eventos son: c-call (llamar a una rutina de lenguaje C), c-return (retorno de una rutina de lenguaje C), call (llamar a un método Ruby), class (iniciar una clase o definición de módulo), end (finalizar una clase o definición de módulo), line (ejecute el código en una nueva línea), raise (levante una excepción) y return (regrese de un método de Ruby). El seguimiento está deshabilitado dentro del contexto de proc.

Aquí está un ejemplo práctico:

class Test 
    def test 
    a = 1 
    b = 2 
    end 
end 

set_trace_func proc { |event, file, line, id, binding, classname| 
    printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname 
} 

t = Test.new 
t.test 

(Nota:. No intente esto en irb a menos que desee una enorme pantalla de desplazamiento de texto) La salida resultante es:

line test.rb:11    false 
    c-call test.rb:11  new Class 
    c-call test.rb:11 initialize Object 
c-return test.rb:11 initialize Object 
c-return test.rb:11  new Class 
    line test.rb:12    false 
    call test.rb:2  test  Test 
    line test.rb:3  test  Test 
    line test.rb:4  test  Test 
    return test.rb:4  test  Test 

Puede jugar con la cadena de formato anterior para obtener solo los resultados que desea registrar (por ejemplo, parece que solo le interesan los eventos call). Espero que eso ayude, ¡y buena suerte al ordenar todas esas pruebas unitarias!

Answer 2

que quería incluir el segundo-past-the-minute el evento sucedió en, así como el tiempo que se gasta en cada función

start = DateTime.now.strftime('%Q').to_i/1000.0 
set_trace_func proc { |event, file, line, id, binding, classname| 
    now_ms = DateTime.now.strftime('%Q').to_i/1000.0 
    duration = '%.3f' % (now_ms - start) 
    start = DateTime.now.strftime('%Q').to_i/1000.0 
    printf "%s %s %8s %s:%-2d %10s %8s\n", DateTime.now.strftime("%S.%L"), duration, event, file, line, id, classname 
} 

AdminUser.create(password: "password", password_confirmation: "password", email: email) 

set_trace_func nil 

yo estaba tratando de depurar por qué se tardó tanto tiempo para crear usuarios e inicie sesión en ActiveAdmin.

05.761 0.000 c-return /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:51  to_s String 
05.761 0.000 c-call /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:51 __bc_crypt BCrypt::Engine 
09.736 63.975 c-return /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:51 __bc_crypt BCrypt::Engine 
09.736 0.000 return /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:59 hash_secret BCrypt::Engine 
09.736 0.000 c-call /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/password.rb:46  new Class 

Y desde que yo sepa Rubí pasado más de un minuto en __bc_crypt.

Answer 3

Recientemente, set_trace_func se desaprobó:

Nota: este método es obsoleto, por favor utilice punto de rastreo en su lugar.

Podemos usar punto de rastreo, que respalda set_trace_func, en su lugar:

trace = TracePoint.new(:call) do |tp| 
    puts "#{tp.defined_class}##{tp.method_id} got called (#{tp.path}:#{tp.lineno})" 
end 

trace.enable 
# do stuff here 
trace.disable 

Esto es incluso más potente que set_trace_func porque se puede activar y desactivar a su conveniencia. Usted puede conectar selectivamente en los siguientes eventos: :line, :class, :end, :call, :return, :c_call, :c_return, :raise, :b_call, :b_return, :thread_begin, :thread_end

Aquí un ejemplo completo:

class MyClass 
    def initialize 
    end 
    def y 
    z 
    end 
    def z 
    1 + 1 
    end 
end 

trace = TracePoint.new(:call) do |tp| 
    puts "#{tp.defined_class}##{tp.method_id} got called (#{tp.path}:#{tp.lineno})" 
end 

trace.enable # note 
MyClass.new.y 
trace.disable 
    # MyClass#initialize got called (./trace.rb:4) 
    # MyClass#y got called (./trace.rb:7) 
    # MyClass#z got called (./trace.rb:10)