Tracing in Ruby

Per venire a capo di situazioni intricate è spesso utile tracciare l'esecuzione del programma per individuare il punto esatto dove il comportamento effettivo si discosta da quello atteso. Ruby offre diversi strumenti per ricavare informazioni utili sull'esecuzione del programma. Iniziamo col vedere alcuni semplici strumenti che permettono di tracciare il programma permettendo di capire quale riga di codice si sta eseguendo.

Tracing

Per individuare semplicemente il nome del file e il numero della linea di codice basta usare le keyword __FILE__ e __LINE__ che forniscono il nome del file e la posizione. Un utile impiego di queste keyword è nell'output di messaggi di debug, ad esempio se volessimo aggiungere alle nostre applicazioni un livello di debug possiamo fornire in output anche il nome del file e la riga:

if $DEBUG
  puts "[DEBUG] Some useful messages at Line #{__LINE__} in #{__FILE__}"
end

Uno strumento molto più potente è fornito attraverso la costante SCRIPT_LINES__ che se opportunamente inizializzata conterrà tutte le righe dei file inclusi nel programma. Per includere i file caricati con require e load basta inizializzare la costante SCRIPT_LINES__ come un hash:

SCRIPT_LINES__ = {}

Dopodiché ogni file caricato andrà a popolare l'hash. Ad esempio un semplice

require 'open-uri'

causerà l'inserimento nell'hash di tutti i file di cui viene fatto il parsing che saranno anche le chiavi di SCRIPT_LINES__:

>> puts SCRIPT_LINES__.keys
/usr/lib/ruby/1.8/parsedate.rb
/usr/lib/ruby/1.8/uri/http.rb
/usr/lib/ruby/1.8/uri/mailto.rb
/usr/lib/ruby/1.8/uri/ldap.rb
/usr/lib/ruby/1.8/uri/https.rb
/usr/lib/ruby/1.8/open-uri.rb
/usr/lib/ruby/1.8/rational.rb
/usr/lib/ruby/1.8/date/format.rb
/usr/lib/ruby/1.8/uri/common.rb
/usr/lib/ruby/1.8/uri.rb
/usr/lib/ruby/1.8/uri/ftp.rb
/usr/lib/ruby/1.8/uri/generic.rb
/usr/lib/ruby/1.8/time.rb

I valori dell'hash saranno degli array di stringhe contenenti il codice sorgente di ogni file. Se si vuole invece includere anche il file sorgente occorre inserirlo riga per riga nell'hash, ad esempio inizializzandolo in questo modo:

SCRIPT_LINES__ = {__FILE__ => File.readlines(__FILE__)}

Per accedere poi alla linea voluta basta accedere al valore desiderato dell'hash indicando il nome del file e la riga. Ad esempio

SCRIPT_LINES__['/usr/lib/ruby/1.8/uri.rb'][1]

produrrà in output la seconda linea del file uri.rb.

Questa costante viene utilizzata principalmente nella costruzione di strumenti di debugging e di coverage ma in alcuni casi è utile anche nelle normali applicazioni.

Kernel

Passiamo ora ad alcuni metodi del modulo Kernel che permettono di tracciare l'esecuzione di un'applicazione. Il primo metodo è trace_var che permette di tracciare i valori assunti da una variabile globale. trace_var prende come argomenti il simbolo rappresentante la variabile da tracciare e un oggetto Proc (o una stringa) da valutare o un blocco da invocare. Ad esempio:

trace_var(:$sensor) {|value|
  puts "Attention: $sensor is #{value}"
}

Dopo ciò ad ogni variazione della variabile $sensor viene eseguito il blocco. Nel nostro caso avremo:

>> $sensor = 1000
Attention: $sensor is 1000
=> 1000
>> $sensor = 0
Attention: $sensor is 0
=> 0

Per terminare il tracciamento della variabile va invece chiamato il metodo untrace_var.

Un altro interessante metodo di Kernel è set_trace_func che permette di invocare un blocco ad ogni linea di codice eseguita in un programma. I parametri associati al blocco, che contengono delle utili le informazioni relative al codice eseguito, sono sei:

• il tipo di evento che si verifica
• il nome del file
• il numero di linea
• il nome del metodo
• il binding
• il nome della classe

I possibili eventi sono:

• call: chiamata ad un metodo Ruby
• return: ritorno da un metodo Ruby
• class: inizio della definizione di una classe o di un modulo
• end: fine della definizione di una classe o di un modulo
• line: esecuzione di una nuova linea di codice
• raise: eccezione
• c-call: chiamata ad una funzione C
• c-return: ritorno da una funzione C

Tracciando una semplice applicazione con set_trace_func:

 1 set_trace_func lambda {|event, file, line, meth, binding, classname| 
 2   puts "[#{event}]t#{file}:#{line}t#{classname} #{meth}" 
 3 }
 4 
 5 class Player
 6   def initialize
 7     @tm = Time.now
 8   end
 9 end
10 
11 e = Player.new

otteniamo in output delle interessanti informazioni sull'esecuzione del programma:

[line]      stf_example.rb:5    false
[c-call]    stf_example.rb:5    Class inherited
[c-return]  stf_example.rb:5    Class inherited
[class]     stf_example.rb:5    false
[line]      stf_example.rb:6    false
[c-call]    stf_example.rb:6    Module method_added
[c-return]  stf_example.rb:6    Module method_added
[end]       stf_example.rb:5    false
[line]      stf_example.rb:11   false
[c-call]    stf_example.rb:11   Class new
[call]      stf_example.rb:6    Player initialize
[line]      stf_example.rb:7    Player initialize
[c-call]    stf_example.rb:7    Time now
[c-call]    stf_example.rb:7    Time initialize
[c-return]  stf_example.rb:7    Time initialize
[c-return]  stf_example.rb:7    Time now
[return]    stf_example.rb:8    Player initialize
[c-return]  stf_example.rb:11   Class new

Dove i numeri di riga permettono di seguire semplicemente il flusso del programma. Si notino anche gli eventi line che scandiscono l'avanzamento del programma attraverso le varie linee di codice.

BackTrace

Quando invece si vogliono conoscere le informazioni relative ad un'eccezione basta utilizzare il metodo Exception.backtrace che fornisce un array di stringhe contenenti tutte le informazioni disponibili sull'eccezione sollevata. Vediamo un esempio illustrativo:

1 def divisione(a,b)
 2   a.div(b)
 3 end
 4
 5 def div_quadrato(a,b)
 6   divisione(a*a, b*b)
 7 end
 8
 9 begin
10   div_quadrato(2, 0)
11 rescue => e
12   puts e.class
13   puts e.backtrace
14 end

Eseguendo questo programma otteniamo un output del genere:

$ ruby backtrace_example.rb
ZeroDivisionError
backtrace_example.rb:2:in 'div'
backtrace_example.rb:2:in 'divisione'
backtrace_example.rb:6:in 'div_quadrato'
backtrace_example.rb:10

Dove viene mostrata la riga che ha sollevato l'eccezione e tutti i riferimenti ai vari metodi chiamati. In pratica ogni elemento dell'array restituito da Exception.backtrace rappresenta una riga del backtrace: il primo elemento dell'array è la riga che ha causato l'eccezione e poi via via in ordine tutte le altre righe.

Tracer

Concludiamo con la libreria tracer appositamente scritta per il tracing. Comunemente viene caricata usando l'opzione -r dell'interprete ruby. La peculiarità di tracer è quella di riuscire a tracciare un programma dall'esterno. Tracciando l'esempio visto nel paragrafo precedente, questa volta ovviamente senza far sollevare nessuna eccezione, otteniamo:

$ ruby -rtracer example.rb
#0:example.rb:1::-: def divisione(a,b)
#0:example.rb:1:Module:>: def divisione(a,b)
#0:example.rb:1:Module:<: def divisione(a,b)
#0:example.rb:5::-: def div_quadrato(a,b)
#0:example.rb:5:Module:>: def div_quadrato(a,b)
#0:example.rb:5:Module:<: def div_quadrato(a,b)
#0:example.rb:9::-: begin
#0:example.rb:10::-:   div_quadrato(2, 1)
#0:example.rb:5:Object:>: def div_quadrato(a,b)
#0:example.rb:6:Object:-:   divisione(a*a, b*b)
#0:example.rb:6:Fixnum:>:   divisione(a*a, b*b)
#0:example.rb:6:Fixnum:<:   divisione(a*a, b*b)
#0:example.rb:6:Fixnum:>:   divisione(a*a, b*b)
#0:example.rb:6:Fixnum:<:   divisione(a*a, b*b)
#0:example.rb:1:Object:>: def divisione(a,b)
#0:example.rb:2:Object:-:   a.div(b)
#0:example.rb:2:Fixnum:>:   a.div(b)
#0:example.rb:2:Fixnum:<:   a.div(b)
#0:example.rb:3:Object:<: end
#0:example.rb:7:Object:<: end

Dove il primo elemento #0 rappresenta il numero di thread, il secondo è il nome del file seguito dal numero di riga, dalla classe, dall'evento e dalla riga di codice eseguita. Gli eventi hanno il seguente significato:

È possibile utilizzare tracer anche come libreria all'interno di un programma:

require 'tracer'

def divisione(a,b)
  a.div(b)
end

def div_quadrato(a,b)
  divisione(a*a, b*b)
end

trace = Tracer.new
trace.on do
  div_quadrato(2, 1)
end

Dove dopo aver creato un nuovo oggetto Tracer lo attiviamo su una definita porzione di codice ottenendo:

$ ruby example.rb
#0:example.rb:17::-:   div_quadrato(2, 1)
#0:example.rb:7:Object:>: def div_quadrato(a,b)
#0:example.rb:8:Object:-:   divisione(a*a, b*b)
#0:example.rb:8:Fixnum:>:   divisione(a*a, b*b)
#0:example.rb:8:Fixnum:<:   divisione(a*a, b*b)
#0:example.rb:8:Fixnum:>:   divisione(a*a, b*b)
#0:example.rb:8:Fixnum:<:   divisione(a*a, b*b)
#0:example.rb:3:Object:>: def divisione(a,b)
#0:example.rb:4:Object:-:   a.div(b)
#0:example.rb:4:Fixnum:>:   a.div(b)
#0:example.rb:4:Fixnum:<:   a.div(b)
#0:example.rb:5:Object:<: end
#0:example.rb:9:Object:<: end

Usato in questo modo Tracer permette anche di definire dei filtri per limitare l'output prodotto utilizzando il metodo add_filter.

Risulta evidente che tracer è costruito sul metodo set_trace_func che permette anche di scrivere tool per il tracciamento in modo semplice e immediato. Infatti è alla base anche del debugger fornito con Ruby e di RCov un tool per il coverage. L'unico inconveniente di un approccio basato su set_trace_func è costituito dalle prestazioni non proprio esaltanti.