Skip to content

Tracing events: what did i miss?

r edited this page Feb 27, 2011 · 1 revision

A common criticism among programmers who don't generally use debuggers is that stepping through the program is extremely tedious. Therefore in trepan a concerted effort has been made to allow a vast variety of ways to set the granularity of stepping (e.g. "set events", "set different", and the various forms of "step" and "next", "finish". trepan also includes a number of mechanisms to try to make it easy to get to some point in the program quickly, e.g. "step until", "step to", "continue" with a target, temporary and permanent breakpoints, "trace var".

But this acerbates another common problem noticed in debugging: in stepping one realizes that one has "stepped" too far and would like to back up a bit. There are experimental or research debuggers use persistent data structures to allow going backwards in the program. However a much more practical and less ambitious approach is to either print or save in a buffer events as seen during the execution of the program. And this is what is done in trepan.

The trepan command "set trace print on" is similar to "set -x" of POSIX shells. Here is an example:

(trepanx): set auto list on
Running a 'list' command each time we enter the debugger is on.
(trepanx): set basename on
basename is on.
(trepanx): set trace print on
Print trace events is on.
(trepanx): step until i == 3
-- (square.rb:2 @12)
1.upto(5) do |i|
-> (integer.rb:128 remapped integer.rb:128 @0)
return to_enum :upto, val unless block_given?
-- (integer.rb:128 remapped integer.rb:128 @3)
return to_enum :upto, val unless block_given?
-- (integer.rb:130 remapped integer.rb:130 @17)
i = self
-- (integer.rb:131 remapped integer.rb:131 @21)
while i <= val
-- (integer.rb:132 remapped integer.rb:132 @30)
yield i
-> (square.rb:2 @0)
1.upto(5) do |i|
-- (square.rb:3 @4)
puts "square of #{i} is #{square}"
-> (fixnum.rb:179 remapped fixnum.rb:179 @0)
def to_s(base=10)
-- (fixnum.rb:179 remapped fixnum.rb:179 @4)
def to_s(base=10)
-- (fixnum.rb:180 remapped fixnum.rb:180 @9)
Rubinius.invoke_primitive :fixnum_to_s, self, base
-- (square.rb:3 @12)
puts "square of #{i} is #{square}"
-> (fixnum.rb:179 remapped fixnum.rb:179 @0)
def to_s(base=10)
-- (fixnum.rb:179 remapped fixnum.rb:179 @4)
def to_s(base=10)
...
ensure_open_and_writable
-- (io.rb:1668 remapped io.rb:1668 @30)
if @sync
-- (io.rb:1669 remapped io.rb:1669 @34)
prim_write(data)

-- (io.rb:1679 remapped io.rb:1679 @117)
data.size
-- (io.rb:1165 remapped io.rb:1165 @99)
write DEFAULT_RECORD_SEPARATOR unless str.suffix?(DEFAULT_RECORD_SEPARATOR)
-> (square.rb:2 @0)
1.upto(5) do |i|
-- (square.rb:3 @4)
puts "square of #{i} is #{square}"
no debugger
  1   	odd, square = 1,1
  2   	1.upto(5) do |i|
  3 ->	  puts "square of #{i} is #{square}"
  4   	  odd += 2
  5   	  square += odd
  6   	end
(trepanx): 

But getting back to a problem previously posed, what if you've just stepped too far because you've asked for the wrong kind of stepping and want to see what you missed? For this, one can save the results in a buffer and see the event history on demand using "set trace buffer on". Here is an example:

(trepanx): set trace print off
Print trace events is off.
(trepanx): set trace buffer on
Saving trace events in a buffer is on.
(trepanx): next
square of 3 is 9
-- (square.rb:4 @27)
odd += 2
no debugger
  1   	odd, square = 1,1
  2   	1.upto(5) do |i|
  3   	  puts "square of #{i} is #{square}"
  4 ->	  odd += 2
  5   	  square += odd
  6   	end
(trepanx): step until i==4
step until i==4
-- (integer.rb:131 remapped integer.rb:131 @21)
while i <= val
126   	
127   	  def upto(val)
128   	    return to_enum :upto, val unless block_given?
129   	
130   	    i = self
131 ->	    while i <= val
132   	      yield i
133   	      i += 1
134   	    end
135   	    self
(trepanx): show trace buffer 0
show trace buffer 0
------------------------------------    -2 ------------------------------------
-- (integer.rb:131 remapped integer.rb:131 @27)
-- (integer.rb:131 remapped integer.rb:131 @37)
-- (integer.rb:131 remapped integer.rb:131 @34)
-- (integer.rb:131 remapped integer.rb:131 @35)
------------------------------------    -1 ------------------------------------
-- (integer.rb:131 remapped integer.rb:131 @21)
no debugger
(trepanx): 

The separator lines with the minuses with -2, and -1 are there to relate what happened in between each stopping point which brought you to the debugger. "show trace buffer 0" starts printing from the first recorded entry.