ghci debugger :trace command does not always extend trace history

[Peter Hercek]

Hi Simon ... and whoever thinks he/she can help me with the right way of 
debugging with ghci,

Sorry for the long post but I cannot explain more shortly what I would 
like to be able to do ... and maybe you find my ":find" and ":monitor" 
commands at the end useful ... and maybe you can propose some other 
useful user defined commands for ghci which were not mentioned in Claus' 
tutorial :-)

Ok, so it is not a bug because each trace command creates a new context 
and trace history is context specific. This means my question now is: 
How can I get access to trace history of a nested trace command which 
just finished?
Here are some explanations so that we understand each other:
The top level trace of my old example is ":trace test 0".
The nested trace of my old example is ":trace z".
I would like to get access to the trace history of the nested trace 
after the nested trace finishes (e.g. after the command ":trace z" 
finished by printing the z value).
Or the other option would be: How to launch ":trace z" so that a new 
nested trace is not created but the current trace (the one before 
launching ":trace z") is extended?

I know I can use ":trace" to continue the current trace but this 
requires that I have some suitable breakpoint later on a place where 
value z is already forced and before the interesting trace history is 
not replaced with newer stuff. It may not be trivial to find such a place.
Other option would be to place breakpoints on all the interesting places 
which lead to the computation of the result being forced with ":trace 
<varName>" and investigate the traces in the nested context. The problem 
here is that it is more work. If I would know the result first then I 
could focus only on the places which are the probable reason of the 
wrong value, moreover the lure of ":find" is tempting (I explain ":find" 
later). Typically the situation is more complicated (there are more 
options) than my small example.

My requests/questions may look strange, but here is reasoning why I 
think I need the functionality. If you have better approach to debugging 
please let me know. Maybe there is still some interesting tutorial I did 
not read about ghc debugging or I just forgot something.

When I debug, I typically know what is probably wrong based on the 
program output. So I place a breakpoint at one logical step before the 
output. When stopped at the breakpoint I force variables which do not 
need to stay lazy and from which the program output is printed. Then I 
can see if some part of the force result/output is unexpected. Then I 
would like to search the trace history to see values of variables which 
probably contributed to the wrong value of the force result/output. I 
hoped that using :trace instead of force would append the trace history.

This backward search for a bug means less work since I need to 
investigate only the path from the dynamic evaluation tree root (the 
wrong program result) to a given node where the bug is. An ability to 
access trace history of a value I just forced would save me some program 
restarts. How much restarts would be saved depends on the trace history 
depth and my ability not to get lost in the order of lazy calls. If I do 
not have access to the trace history, the only option is to put a 
breakpoint at a place where the variable value I wanted to check is 
available and restart the program so that I can check the value.

Since there is no way to print partially applied functions this value 
based approach is probably the only one working. This is supported by 
recommendations to use printf debugging.

One more reason I would like to learn how to access the trace history of 
a forced value is that my :monitor commands conflict with ghci trace 
history. I was able to implement :monitor and :find commands based on 
Claus' ghci scripting tutorial:

:monitor displays value of a given variable at a given location while 
discarding all the other output. It is a way to do printf debugging 
solely from ghci without changing source code (i.e. without adding 
Debug.Trace.trace calls). :monitor (used together with ":x") is not 
always better than printf debugging  because it discards program output 
too, and cannot add an identifier to scope. But often it is ... at least 
for me because it separates printf debugging (defined using ":monitor" 
commands in a script I source with ":.") from the source code.

:find finds a variable name in trace history, prints its value, and a 
location where it was found. The location is needed here because of name 
conflicts. The value located may not be the right one. Taking static 
scopes into account could discard a lot of false finds (not all of 
them). I think that taking static scopes and (maybe more detailed) trace 
history into account could rule out all false positives. But nobody 
wants to implement this in a ghci script ... I guess :-)

Currently my :monitor command makes holes in trace history, lowering the 
value of :find command :-(

If you are interested you can find :find and :monitor implementations 
here: http://www.hck.sk/users/peter/pub/.ghci

It looks to me that the way tracing is done is unfortunate from the 
point of view of scripting custom ghci commands. It would be better to 
have a global trace history which would be activated/deactivated with 
command like ":trace on/off" and this would modify the behavior of the 
rest of the ghci commands appropriately. E.g. :continue would behave 
like :trace (without arguments) when tracing is on. It would be probably 
interesting to have more tracing buffers (but I did not think about this 
much). Now, it is done in a cool functional way which means more 
complicated user defined ghci commands ... unless I'm missing something :-)


Thanks,
Peter.


Simon Marlow wrote:
> Peter Hercek wrote:
>> Hi,
>>
>> I expected ":trace expr" to always add data to the trace history but 
>> it does not do so for CAFs (which are not reduced yet).
>> My point is that the command ":trace z" did not add anything to the 
>> trace history and I cannot check why value z is 2, because value of y 
>> is not in the trace history. Is this the expected behavior? If it is, 
>> how can I make ghci to extend the trace history when "forcing" variables?
>>
>> Peter.
>>
>> Here is the example:
>>
>> status:0 peter at metod [765] ~/tmp
>> % cat a.hs
>> test :: Int -> Int
>> test x =
>>   let y = x+1 in
>>   let z = y+1 in
>>   z
>> status:0 peter at metod [766] ~/tmp
>> % ghci a.hs
>> GHCi, version 6.8.2: http://www.haskell.org/ghc/  :? for help
>> Loading package base ... linking ... done.
>> [1 of 1] Compiling Main             ( a.hs, interpreted )
>> Ok, modules loaded: Main.
>> *Main> :break Main 5
>> Breakpoint 0 activated at a.hs:5:2
>> *Main> :trace test 0
>> Stopped at a.hs:5:2
>> _result :: Int = _
>> z :: Int = _
>> 4    let z = y+1 in
>> 5    z
>> 6
>> [a.hs:5:2] *Main> :back
>> Logged breakpoint at a.hs:(2,0)-(5,2)
>> _result :: Int
>> 1  test :: Int -> Int
>> 2  test x =
>> 3    let y = x+1 in
>> 4    let z = y+1 in
>> 5    z
>> 6
>> [-1: a.hs:(2,0)-(5,2)] *Main> :back
>> no more logged breakpoints
> 
> ok so far - y and z have not been evaluated.
> 
>> [-1: a.hs:(2,0)-(5,2)] *Main> :forward
>> Stopped at a.hs:5:2
>> _result :: Int
>> z :: Int
>> 4    let z = y+1 in
>> 5    z
>> 6
>> [a.hs:5:2] *Main> :trace z
>> 2
> 
> this evaluates z.
> 
>> [a.hs:5:2] *Main> :back
>> Logged breakpoint at a.hs:(2,0)-(5,2)
>> _result :: Int
>> 1  test :: Int -> Int
>> 2  test x =
>> 3    let y = x+1 in
>> 4    let z = y+1 in
>> 5    z
>> 6
> 
> You are going back in the original context, but I presume you were 
> expecting to go back in the evaluation of z.  You can only go back in 
> the context of the current evaluation, however.
> 
> Try this:
> 
> *Main> :break 3
> Breakpoint 4 activated at trace.hs:3:10-12
> *Main> :trace test 0
> Stopped at trace.hs:3:10-12
> _result :: Int = _
> x :: Int = 90
> 2  test x =
> 3    let y = x+1 in
> 4    let z = y+1 in
> [trace.hs:3:10-12] *Main> :history
> -1  : test (trace.hs:4:10-12)
> -2  : test (trace.hs:5:2)
> -3  : test (trace.hs:(2,0)-(5,2))
> <end of history>
> [trace.hs:3:10-12] *Main> :back
> Logged breakpoint at trace.hs:4:10-12
> _result :: Int
> y :: Int
> 3    let y = x+1 in
> 4    let z = y+1 in
> 5    z
> [-1: trace.hs:4:10-12] *Main> :back
> Logged breakpoint at trace.hs:5:2
> _result :: Int
> z :: Int
> 4    let z = y+1 in
> 5    z
> 6
> 
> Cheers,
>     Simon