Tracing events: what did i miss?

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:

   $ trepan /tmp/square.rb
  -- (/tmp/square.rb:1)
  odd, square = 1, 1
  (trepan): set auto list on  # Show source listing automatically
  Running a 'list' command each time we enter the debugger is on.
  (trepan): set basename on   # Just the basename of file names
  basename is on.
  (trepan): set events line 
  Trace events we may stop on:
  	line
  (trepan): set trace print on
  Print trace events is on.
  (trepan): step until i == 3 # Note all the output below
  -- (square.rb:2)
  1.upto(5) do |i|
  -- (square.rb:3)
  puts "square of #{i} is #{square}"
  square of 1 is 1
  -- (square.rb:4)
  odd += 2
  -- (square.rb:5)
  square += odd
  -- (square.rb:3)
  puts "square of #{i} is #{square}"
  square of 2 is 4
  -- (square.rb:4)
  odd += 2
  -- (square.rb:5)
  square += odd
  -- (square.rb:3)
  puts "square of #{i} is #{square}"
    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
    7    	  
  (trepan): 

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:

  (trepan): set events c_call c_return line
  Trace events we may stop on:
  	c_call, c_return, line
  (trepan): set trace print off
  Print trace events is off.
  (trepan): set trace buffer on
  Saving trace events in a buffer is on.
  (trepan): next
  square of 3 is 9
  -- (square.rb:4)
  odd += 2
    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
    7    	  
  (trepan): step until i==4
  -- (square.rb:3)
  puts "square of #{i} is #{square}"
    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
    7    	  
  (trepan): show trace buffer 0  # what did I miss? 
  c-call CFUNC to_s /tmp/square.rb at line 3:
      puts "square of #{i} is #{square}"
  c-return CFUNC to_s 
  c-call CFUNC to_s 
  c-return CFUNC to_s 
  c-call CFUNC puts 
  c-call CFUNC puts 
  c-call CFUNC write 
  c-return CFUNC write 
  c-call CFUNC write 
  c-return CFUNC write 
  c-return CFUNC puts 
  c-return CFUNC puts 
  ------------------------------------    -2   ------------------------------------
  line BLOCK block in <top /tmp/square.rb> /tmp/square.rb at line 4
  	VM offset 26:
      odd += 2
  line BLOCK block in <top /tmp/square.rb> /tmp/square.rb at line 5
  	VM offset 38:
      square += odd
  ------------------------------------    -1   ------------------------------------
  line BLOCK block in <top /tmp/square.rb> /tmp/square.rb at line 3
  	VM offset 2:
      puts "square of #{i} is #{square}"
  (trepan): 

To make the output more interesting above, I’ve included the C calls and returns that occur in “puts”. 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.

Before showing the buffer, I issued two debugger stepping commands: “next” produced all those c-call and c-return events with for “to_s”, “puts” and “write”. And after this, I issued “step until” which had two line events.

But if you use a negative number in “show trace buffer”, printing starts from what happened starting from that many stops in the debugger previously. For example:

  (trepan): show trace buffer -2 # What happened bewteen last 2 stops?
  ------------------------------------    -2 ------------------------------------
  line BLOCK block in <top /tmp/square.rb> /tmp/square.rb at line 4
  	VM offset 26:
      odd += 2
  line BLOCK block in <top /tmp/square.rb> /tmp/square.rb at line 5
  	VM offset 38:
      square += odd
  ------------------------------------    -1   ------------------------------------
  line BLOCK block in <top /tmp/square.rb> /tmp/square.rb at line 3
  	VM offset 2:
      puts "square of #{i} is #{square}"
  (trepan):