Come posso registrare ogni metodo chiamato in un programma Ruby?

Question

Ho ereditato una grande pila di codice Ruby che è, francamente, quasi impossibile da capire per un mortale come me. In realtà è un codice di test unitario Rspec, ma la struttura è "molto insolita" per dirla in modo carino.

Quello che mi piacerebbe essere in grado di fare è eseguire il codice, e hanno le seguenti informazioni registrate da qualche parte:

• ogni metodo che viene richiamato, tra cui il nome della classe che definisce il metodo, e il nome del file in cui è stato definito il metodo invocato (sì, abbiamo la stessa classe/metodo definito in più file diversi ed è difficile sapere quale viene invocato)
• (facoltativamente) i parametri passati a ciascun metodo invocato

Con quello, potrei cominciare a provare a refactoring esso. Senza di esso, sarà molto difficile risolverlo a causa delle dimensioni del codice di base (20k + casi di test unitari).

Non posso permettermi di entrare ed eseguire le modifiche all'ingrosso al codice in esecuzione, perché si interrompe quando si usa persino un linguaggio aspro attorno ad esso (cioè spesso). Invece, ho bisogno di essere in grado di strumentare il codice nel suo stato esistente, o con modifiche minime a ciò che esiste ora.

C'è un modo per registrare questo livello di dettaglio senza apportare modifiche all'ingrosso al codice base? Ho dato un'occhiata al profiler di Ruby per vedere se poteva aiutare, e probabilmente potrebbe; Sono curioso di sapere se esiste un modo migliore (in particolare, registrare il nome file che contiene il metodo invocato).

Grazie in anticipo

Answer 1

Questo è sicuramente possibile - in realtà, c'è anche un metodo per esso! Basta aggiungere questo da qualche parte nel codice prima del punto che si desidera avviare le cose di registrazione:

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

La salsa segreta che si desidera proviene da Kernel#set_trace_func, come osservato in precedenza:

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

Stabilisce proc come gestore per la traccia o disabilita la traccia se il parametro è nil. proc accetta fino a sei parametri: un nome evento, un nome file, un numero di riga, un ID oggetto, un'associazione e il nome di una classe. proc viene invocato ogni volta che si verifica un evento. Gli eventi sono: c-call (chiamare una routine in linguaggio C), c-return (ritorno da una routine in linguaggio C), call (chiamare un metodo Ruby), class (avviare una definizione di classe o modulo), end (terminare una definizione di classe o modulo), line (esegue codice su una nuova riga), raise (genera un'eccezione) e return (restituisce da un metodo Ruby). La traccia è disabilitata nel contesto di proc.

Ecco un esempio pratico:

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:. Non provare questo in irb meno che non si vuole uno schermo a scorrimento enorme del testo) L'output risultante è:

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 

È possibile giocare con la stringa di formattazione sopra per ottenere solo i risultati che si desidera registrare (ad esempio, sembra che siate interessati solo agli eventi call). Spero che ti sia d'aiuto, e buona fortuna con lo smistamento di tutti quei test unitari!

Answer 2

ho voluto includere il secondo-past-the-minute dell'evento inviteranno a, così come per quanto tempo è stato speso in ogni funzione

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 

Stavo cercando di eseguire il debug perché ci sia voluto così tanto tempo per creare utenti e accedere ad 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 

E da quello che so di Ruby trascorso più di un minuto in __bc_crypt.

Answer 3

Recentemente, è stata sconsigliata set_trace_func:

Nota: questo metodo è obsoleto, si prega di utilizzare tracepoint invece.

Possiamo usare tracepoint, che sostiene set_trace_func, invece:

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 

Questo è in realtà ancora più potente di set_trace_func perché è possibile attivare e disattivare a vostro piacimento. È possibile collegare in modo selettivo i seguenti eventi: :line, :class, :end, :call, :return, :c_call, :c_return, :raise, :b_call, :b_return, :thread_begin, :thread_end

Ecco un esempio 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)