Comment enregistrer toutes les méthodes appelées dans un programme Ruby?

Question

J'ai hérité d'un gros paquet de code Ruby, franchement, impossible à comprendre pour un mortel comme moi. C'est en fait le code de test unitaire de Rspec, mais la structure est "très inhabituelle" pour le dire gentiment.

Ce que je voudrais être en mesure de faire est de lancer le code, et ont les informations suivantes connecté quelque part:

• chaque méthode qui obtient invoquée, y compris le nom de la classe qui définit la méthode, et le nom de fichier où la méthode invoquée a été définie (oui, nous avons la même classe/méthode définie dans plusieurs fichiers différents, et il est difficile de savoir lequel est appelé)
• (facultativement) les paramètres passés à chaque méthode invoqué

Avec ça, je pourrais commencer à essayer de le refactoriser. Sans cela, il sera très difficile de le résoudre, en raison de la taille de la base de code (20k + unités de test unitaires).

Je ne peux pas me permettre d'effectuer des modifications en gros sur le code en cours d'exécution, car cela casse lorsque vous utilisez même un langage sévère (c'est-à-dire fréquemment). Au lieu de cela, j'ai besoin d'être en mesure d'instrument le code dans son état existant, ou avec des changements minimes à ce qui existe maintenant.

Existe-t-il un moyen de consigner ce niveau de détail sans apporter de modifications importantes à la base de code? J'ai jeté un coup d'œil au profileur Ruby pour voir si cela pouvait aider, et ça pourrait probablement; Je suis curieux de savoir s'il existe un meilleur moyen (en particulier de consigner le nom du fichier contenant la méthode invoquée).

Merci à l'avance

Answer 1

C'est certainement possible - en fait, il y a même une méthode pour elle! Il suffit d'ajouter cela quelque part dans votre code avant le point que vous voulez commencer les choses d'exploitation:

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

La sauce secrète que vous voulez vient de Kernel#set_trace_func, comme il est indiqué ci-dessus:

• set_trace_func (proc) => proc
• set_trace_func (néant) => nil

Définit proc en tant que gestionnaire pour le suivi ou désactive le suivi si le paramètre est nil. proc prend jusqu'à six paramètres: un nom d'événement, un nom de fichier, un numéro de ligne, un identifiant d'objet, une liaison et le nom d'une classe. proc est invoqué chaque fois qu'un événement se produit. Les événements sont: c-call (appelez une routine en langage C), c-return (retour d'une routine en langage C), call (appelez une méthode Ruby), class (commencez une définition de classe ou de module), end (terminez une définition de classe ou de module)), line (code d'exécution sur une nouvelle ligne), raise (lever une exception) et return (retour d'une méthode Ruby). Le suivi est désactivé dans le contexte de proc.

Voici un exemple pratique:

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 

(Note:. Ne pas essayer à irb sauf si vous voulez un grand écran de défilement du texte) La sortie résultante est:

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 

Vous pouvez jouer avec la chaîne de formatage ci-dessus pour obtenir uniquement les résultats que vous souhaitez enregistrer (par exemple, il semble que vous êtes uniquement intéressé par les événements call). J'espère que cela aide, et bonne chance avec le tri de tous ces tests unitaires!

Answer 2

Je voulais inclure les secondes passés de la minute de l'événement happend à ainsi que combien de temps a été passé dans chaque fonction

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 

J'ai essayé de déboguer pourquoi il a fallu tant de temps pour créer des utilisateurs et connectez-vous à 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 

Et à partir de ce que je sais Ruby a passé plus d'une minute à __bc_crypt.

Answer 3

Récemment, set_trace_func a été dépréciée:

Remarque: cette méthode est obsolète, s'il vous plaît utiliser à la place de trace.

Nous pouvons utiliser de trace, qui soutient set_trace_func, au lieu:

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 

Ceci est en fait encore plus puissant que set_trace_func parce que vous pouvez activer et désactiver à votre convenance. Vous pouvez choisir d'accrocher dans les événements suivants: :line, :class, :end, :call, :return, :c_call, :c_return, :raise, :b_call, :b_return, :thread_begin, :thread_end

Voici un exemple complet:

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)