Was?

ruby-prof ist ein Ruby-Profiler. Er ist nicht nur deutlich schneller als profile aus der Standardlibrary, sondern unterstützt u.a. auch rekursive Aufrufe, kann mehrere Threads gleichzeitig analysieren, und Call-Graph-Profile erzeugen.

Installieren & Einrichten

ruby-prof ist wie gewohnt per Rubygems verfügbar:

gem install ruby-prof

Unter unixoiden Betriebssystemen wird ein C-Compiler vorausgesetzt, und Debian-User müssen wie gewohnt das ruby-dev-Paket installiert haben.

In dieser Einführung habe ich ruby-prof 0.6.0 verwendet.

Verwenden

Als Testprogramm nehmen wir die Lösung von James Edward Gray II für das Ruby Quiz #154 her. In diesem Quiz ging es darum eine gegebene Summe Geld in die kleinste mögliche Anzahl von Münzen zu wählen. Nachdem das finden dieser kleinsten Anzahl von Münzen für grosse Beträge (z.b. 1234) sehr aufwendig ist (nachdem es sehr viele mögliche Kombinationen gibt), eignet es sich ganz gut um mit ruby-prof etwas herumzuspielen. Man muss das Programm lediglich etwas modifizieren und die __FILE__-Abfrage am Ende entfernen, sonst funktioniert das analysieren mit der ruby-prof-Binary nicht.

ruby-prof unterstützt drei Wege um ein Programm zu analysieren. Die erste besteht in der Verwendung der ruby-prof-Binary:

ruby-prof make_change.rb 1234

Damit wird das Programm ausgeführt, und ruby-prof gibt uns am Ende eine schöne Analyse aus:

Thread ID: 218880
Total: 4.726782

 %self     total     self     wait    child    calls  name
 63.10      4.56     2.98     0.00     1.58    30056  Array#each
  7.23      0.41     0.34     0.00     0.07   120162  Hash#[]
  6.93      0.33     0.33     0.00     0.00   120217  Array#+
  5.45      0.26     0.26     0.00     0.00   120217  Fixnum#+
  5.36      0.25     0.25     0.00     0.00   120217  Fixnum#==
  5.36      0.25     0.25     0.00     0.00   120216  Fixnum#<
  3.40      4.72     0.16     0.00     4.56       54  Hash#each
  1.64      0.08     0.08     0.00     0.00    31428  Hash#[]=
  1.46      0.07     0.07     0.00     0.00    31428  Hash#default
  0.02      4.73     0.00     0.00     4.72        1  Kernel#loop
  0.01      4.73     0.00     0.00     4.73        1  Kernel#load
  0.01      0.00     0.00     0.00     0.00        1  Array#each-1
  0.01      0.00     0.00     0.00     0.00        2  Enumerable#sort_by
  0.01      0.00     0.00     0.00     0.00       54  Kernel#inspect
  0.00      0.00     0.00     0.00     0.00      101  Fixnum#<=>
  0.00      0.00     0.00     0.00     0.00       58  Fixnum#-@
  0.00      0.00     0.00     0.00     0.00        1  Array#inspect
  0.00      0.00     0.00     0.00     0.00       54  Fixnum#to_s
  0.00      0.00     0.00     0.00     0.00       53  Hash#empty?
  0.00      0.00     0.00     0.00     0.00        2  IO#write
  0.00      4.73     0.00     0.00     4.73        1  Object#make_change
  0.00      0.00     0.00     0.00     0.00        1  Kernel#p
  0.00      0.00     0.00     0.00     0.00        1  Array#map
  0.00      0.00     0.00     0.00     0.00        1  Kernel#Integer
  0.00      0.00     0.00     0.00     0.00        1  Module#method_added
  0.00      0.00     0.00     0.00     0.00        1  Fixnum#zero?
  0.00      0.00     0.00     0.00     0.00        1  Array#empty?
  0.00      4.73     0.00     0.00     4.73        0  Global#[No method]

Wie man unschwer erkennen kann wird die meiste Zeit in Array#each verbracht. Die erste Kolumne ("%self") sagt uns wieviel Prozent der Zeit in dieser Methode verbracht wurde. "total" gibt die ganze Zeit in Sekunden an, die in dieser Methode verbracht wurde, inklusive der Zeit aller aufgerufenen Methoden. "self" ist nur die Zeit die in dieser Methode verbracht wurde, usw.

Die Binary unterstützt einige praktische Optionen. So kann man z.b. die Art des Reports auswählen oder die Art der Messmethode bestimmen. Mehr Informationen findet man im Rdoc oder mit dem --help-Switch.

Alternativ dazu kann man auch die ruby-prof-API direkt verwenden. Das ist insbesondere praktisch wenn mann nur kleinen Teile seines Programms oder Library analysieren möchte. Dazu bindet man zuerst ruby-prof ein, und hat dann zwei Möglichkeiten:

• Man verwendet RubyProf.start und RubyProf.end um den Bereich zu markieren den man analysieren möchte:

  RubyProf.start
  # Here be code
  result = RubyProf.stop
  

• Oder man verwendet RubyProf.profile, das einen Block erwartet, welcher analysiert wird:

  RubyProf.profile do
  # Here be code
  end
  

Egal welche Methode man wählt, man kann vorher mit RubyProf.measure_mode= die Methode der Messung bestimmten. Und sobald man das Resultat hat, kann man mit einer der Printer-Klassen einen Report erzeugen:

printer = RubyProf.FlatPrinter.new(result)
printer.print

# Alternativ, wenn nicht nach STDOUT ausgegeben werden soll:
printer.print(STDERR)

print kann als zweites Argument auch einen Options-Hash bekommen, für Details siehe die Rdoc für setup_options.

ruby-prof stellt dabei folgende Printer-Klassen zur Verfügung:

• FlatPrinter: generiert ein flaches Profil als Text. Die Ausgabe weiter oben ist ein Beispiel für den FlatPrinter. Besonders praktisch für einfachere Programme oder Libraries.
• GraphPrinter: generiert einen Call-Graph im Textformat. Diese zeigen für jede aufgerufene Methode an von welcher Methode sie aufgerufen wurde, und welche Methode sie aufgerufen hat. Dieses Format ist insbesondere bei grossen oder komplexen Programmen/Libraries praktisch, da es sehr viele Informationen liefert.
• GraphHtmlPrinter: Gleich wie GraphPrinter, aber statt Text bekommt man HTML, welches die Navigation in grossen Call-Graphs deutlich vereinfacht.
• CallTreePrinter: Ein Ausgabeformat für kcachegrind.

Die dritte Möglichkeit funktioniert indem man unprof.rb per require oder dem -r-Switch in sein Programm einbindet. Dadurch wird ebenfalls das das komplette Programm analysiert, man hat aber keine Möglichkeit wie bei ruby-prof irgendwelche Optionen anzugeben. Und die Autoren raten von dieser Methode auch ab, da sie nur aus historischen Gründen noch funktioniert, und empfehlen stattdessen die ruby-prof-Binary zu verwenden.

Fin

Das wars für dieses mal, nächste Woche: ZenTest.