A volte, soprattutto in quando si sviluppano applicazioni Web molto complesse, capita che le prestazioni non siano eccellenti e occorre quindi rivederne alcune parti. L'ottimizzazione però porta a buoni risultati solo se si sa con precisione quali parti del programma ne rallentano eccessivamente l'esecuzione. Ruby mette a disposizione diversi strumenti per valutare le prestazioni e per capire quali elementi del programma consumano più risorse.
Ruby-prof
Il migliore strumento attualmente disponibile per effettuare il profiling di codice Ruby è ruby-prof installabile sia attraverso RubyGems sia a partire dai sorgenti. ruby-prof permette di valutare diversi parametri come il tempo di esecuzione delle varie chiamate e il consumo di memoria; possiede inoltre un avanzato sistema di reporting.
È possibile eseguire il profiling con ruby-prof in tre modi. Il metodo meno invasivo consiste nell'eseguire il codice da esaminare con l'utility ruby-prof installata con la libreria:
$ ruby-prof test.rb ...output del programma... Thread ID: 3083638540 Total: 0.160000 %self total self wait child calls name 31.25 0.05 0.05 0.00 0.00 20000 IO#write 25.00 0.16 0.04 0.00 0.12 1 Integer#times 25.00 0.04 0.04 0.00 0.00 10000 Fixnum#to_s 18.75 0.12 0.03 0.00 0.09 10000 Kernel#puts 0.00 0.16 0.00 0.00 0.16 0 Global#[No method] 0.00 0.16 0.00 0.00 0.16 1 Kernel#load
Dove test.rb è semplicemente un ciclo del genere:
10_000.times do |i| puts i end
L'output è banale: vengono mostrate le informazioni sui tempi, le percentuali di utilizzo e il numero di chiamate ai vari metodi.
Le opzioni da linea di comando permettono tra l'altro di scegliere il formato del report, il metodo di misurazione e i metodi da mostrare nel report.
In alternativa è possibile utilizzare ruby-prof come libreria:
require 'rubygems' require 'ruby-prof' RubyProf.start 10_000.times do |i| puts i end res = RubyProf.stop output = RubyProf::FlatPrinter.new(res) output.print
In questo caso il codice analizzato è quello compreso tra i metodi start e stop di RubyProf. I risultati sono gli stessi di prima. Più concisamente è possibile utilizzare un blocco associato al metodo profile:
res = RubyProf.profile do
10_000.times do |i|
puts i
end
end
Infine c'è la soluzione veloce. Aggiungendo
require 'unprof'
ad un programma si otterrà in output il report dell'intera applicazione. unprof non fa altro che definire il blocco del metodo Kernel#at_exit, che viene chiamato all'uscita dal programma, in questo modo:
require "ruby-prof"
at_exit {
result = RubyProf.stop
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)
}
RubyProf.start
Così però non è possibile scegliere nessuna impostazione del profiler. Detto questo andiamo a vedere in dettaglio i formati del report e i tipi di misurazione.
Report
I tipi di report a disposizione sono quattro. Nella modalità Flat, vista negli esempi precedenti, viene mostrata per ogni metodo la percentuale di utilizzo, i vari tempi impiegati nell'esecuzione e il numero di chiamate.
Il secondo tipo di report è Graph che, oltre alle informazioni mostrate da Flat, ci dice anche per ogni metodo i nomi dei metodi che chiama e i nomi dei metodi che lo chiamano. Ad esempio tornando al codice visto prima abbiamo:
%total %self total self wait child calls Name
-----------------------------------------------------------------------------
100.00% 0.00% 0.19 0.00 0.00 0.19 0 Global#[No method]
0.19 0.01 0.00 0.18 1/1 Integer#times
-----------------------------------------------------------------------------
0.19 0.01 0.00 0.18 1/1 Global#[No method]
100.00% 5.26% 0.19 0.01 0.00 0.18 1 Integer#times
0.18 0.04 0.00 0.14 10000/10000 Kernel#puts
-----------------------------------------------------------------------------
0.18 0.04 0.00 0.14 10000/10000 Integer#times
94.74% 1.05% 0.18 0.04 0.00 0.14 10000 Kernel#puts
0.04 0.04 0.00 0.00 10000/10000 Fixnum#to_s
0.10 0.10 0.00 0.00 20000/20000 IO#write
-----------------------------------------------------------------------------
0.10 0.10 0.00 0.00 20000/20000 Kernel#puts
52.63% 2.63% 0.10 0.10 0.00 0.00 20000 IO#write
-----------------------------------------------------------------------------
0.04 0.04 0.00 0.00 10000/10000 Kernel#puts
21.05% 1.05% 0.04 0.04 0.00 0.00 10000 Fixnum#to_s
In ogni sezione del report sono riportati il nome e i dati del metodo analizzato contraddistinti dai valori %total e %self mentre nelle righe superiori sono elencati i metodi che lo chiamano e in quelle inferiori i metodi chiamati. Ad esempio considerando la terza sezione del nostro report si deduce che il metodo analizzato è Kernel#puts che è chiamato da Integer#times e che chiama a sua volta Fixnum#to_s e IO#write.
Per ottenere questo report occorre utilizzare la classe RubyProf::GraphPrinter e poi chiamare il metodo print come visto nell'esempio.
C'è poi la modalità HTML Graph (classe RubyProf::GraphHtmlPrinter) che fornisce i dati nello stesso formato ma sotto forma di codice HTML.
C'è infine la modalità Call (classe RubyProf::CallTreePrinter) che mostra l'output nel formato CallTree di KCachegrind. Ad esempio:
Esempio di report in formato CallTree
events: process_time fl=/home/gls/ruby_runtime fn=Kernel::puts 0 40000 cfl=/home/gls/ruby_runtime cfn=IO::write calls=20000 13 13 40000 cfl=/home/gls/ruby_runtime cfn=Fixnum::to_s calls=10000 13 13 30000 fl=/home/gls/ruby_runtime fn=Integer::times 0 80000 cfl=/home/gls/ruby_runtime cfn=Kernel::puts calls=10000 13 13 110000 fl=/home/gls/ruby_runtime fn=Fixnum::to_s 0 30000 fl=/home/gls/test_prof.rb fn=Global::[No method] 12 0 cfl=/home/gls/ruby_runtime cfn=Integer::times calls=1 12 12 190000 fl=/home/gls/ruby_runtime fn=IO::write 0 40000
Anche in questo caso ogni metodo ha una propria sezione e le proprie informazioni che comprendono anche il nome delle funzioni chiamate dal metodo analizzato. Per maggiori informazioni rimando al sito di KCachegrind.
Da linea di comando i tipi di report vanno impostati attraverso l'opzione --printer che accetta i valori flat, graph, graph_html e call_tree.
Misurazioni
ruby-prof permette di effettuare diversi tipi di misurazione, alcuni disponibili solo per alcune piattaforme. Attualmente le misure disponibili sono:
- process time: misura il tempo utilizzato dal processo ed è l'impostazione di default
- wall time: misura il tempo reale di esecuzione, tale valore può risentire degli altri processi in esecuzione sul sistema
- cpu time: misurazione che utilizza i cicli CPU come unità di misura ed è disponibile solo per processori Pentium e PowerPC
- object allocations: misura il numero di oggetti allocati da ogni metodo
- memory usage: misura per ogni metodo l'utilizzo della memoria
Queste ultime due misurazioni richiedono l'utilizzo di un interprete Ruby opportunamente modificato. Tutte le informazioni a riguardo sono nella documentazione di ruby-prof.
Per scegliere tra i vari metodi di misurazione va opportunamente impostato RubyProf.measure_mode che accetta i valori RubyProf::PROCESS_TIME, RubyProf::WALL_TIME, RubyProf::CPU_TIME, RubyProf::ALLOCATIONS e RubyProf::MEMORY. In alternativa è possibile impostare la variabile d'ambiente RUBY_PROF_MEASURE_MODE ad uno dei seguenti valori: process, wall, cpu e allocations.
Da linea di comando invece le modalità di esecuzione vanno impostate attraverso l'opzione --mode che accetta gli stessi valori di RUBY_PROF_MEASURE_MODE.
Ruby Profiler
Oltre alla gemma ruby-prof è possibile utilizzare il profiler distribuito direttamente con Ruby. La differenza tra i due sta nelle prestazioni (ruby-prof è scritto in C ed è notevolmente più veloce) e nelle opzioni disponibili. Per utilizzare il profiler standard basta inserire semplicemente
require 'profile'
nel programma ottenendo in questo modo l'analisi dell'intero sorgente. In pratica il comportamento è simile a quello visto per unprof, in questo caso includendo profile viene definito un blocco END da eseguire all'uscita:
require 'profiler'
END {
Profiler__::print_profile(STDERR)
}
Profiler__::start_profile
dove profiler è la libreria che implementa il profiler standard di Ruby. Con lo stesso esempio visto prima si ottiene un output simile a quello di ruby-prof:
% cumulative self self total
time seconds seconds calls ms/call ms/call name
51.52 0.85 0.85 10000 0.08 0.14 Kernel.puts
23.03 1.23 0.38 20000 0.02 0.02 IO#write
16.36 1.50 0.27 1 270.00 1650.00 Integer#times
9.09 1.65 0.15 10000 0.02 0.02 Fixnum#to_s
0.00 1.65 0.00 1 0.00 1650.00 #toplevel
Per avere un maggior controllo delle operazioni occorre includere direttamente 'profiler' ed utilizzare i metodi start_profile, stop_profile e print_profile del modulo Profiler__. In alternativa è possibile chiamare il profiler direttamente da linea di comando utilizzando l'opzione "-r profile" dell'interprete Ruby.
