[ clisp-Feature Requests-1808029 ] trace with call counters

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

Feature Requests item #1808029, was opened at 2007-10-05 13:42
Message generated for change (Comment added) made by haible
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=351355&aid=1808029&group_id=1355

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Extend ANSI CL
Group: None
Status: Closed
Resolution: Accepted
Priority: 5
Private: No
Submitted By: Basile STARYNKEVITCH (bstarynk)
Assigned to: Nobody/Anonymous (nobody)
Summary: trace with call counters

Initial Comment:
The details of the (trace ...) function behavior is left unspecified by the CL standard.

I suggest that each traced function would emit, in addition to what is actually printed today, a unique call counter.

As a concrete example, currently tracing the famous fact function gives

[5]> (fact 3)
1. Trace: (FACT '3)
2. Trace: (FACT '2)
3. Trace: (FACT '1)
4. Trace: (FACT '0)
4. Trace: FACT ==> 1
3. Trace: FACT ==> 1
2. Trace: FACT ==> 2
1. Trace: FACT ==> 6

I am suggesting that it becomes

[5]> (fact 3)
1. Trace #1: (FACT '3)
2. Trace #2: (FACT '2)
3. Trace #3: (FACT '1)
4. Trace #4: (FACT '0)
4. Trace #4: FACT ==> 1
3. Trace #3: FACT ==> 1
2. Trace #2: FACT ==> 2
1. Trace #1: FACT ==> 6

The rationale is that in real debugging sessions, finding quickly (e.g. with emacs Ctrl-R) the beginning trace matching the ending trace would be much easier.

----------------------------------------------------------------------

>Comment By: Bruno Haible (haible)
Date: 2007-10-11 23:29

Message:
Logged In: YES 
user_id=5923
Originator: NO

>>If, for example, you're at the line
>>   2. Trace: FACT ==> 2
>>and search where it came from, just search backward for "2. Trace:".
>>In Emacs: Ctrl-R 2. Trace:
>
> "2" is call depth, not the call id.
> there could be many different calls with the same call depth in the
same
> emacs buffer, 
> but only one call of a given function with the given call count.

Yes. But when you are on the ending trace of a call "2. Trace: FACT ==> 2"
and
are looking for the corresponding starting trace with the arguments, it
is
always the last occurrence of the regexp "^2. Trace:". Because all calls
between
that starting trace and the ending trace have a higher call depth.
Therefore
   C-M-R ^2\. Trace:
will find it.

Two other remarks:
1) It is not welcome usually that two executions of the same form from a
REP loop
   yield different output. Therefore I would find it useful if the
toplevel REP
   loop would virtually reset the trace counters before every form
evaluation.
   ("virtually" - i.e. implemented without actually traversing the list of
all
   traced functions).
2) A hierarchical counter instead of a single number would allow the user
to more easily
   see the parent and child activations. For example:
   > (trace fact)
   > (list (fact 2) (fact 1))
   1. Trace #1: (FACT '2)
   2. Trace #1-1: (FACT '1)
   3. Trace #1-1-1: (FACT '0)
   3. Trace #1-1-1: FACT ==> 1
   2. Trace #1-1: FACT ==> 1
   1. Trace #1: FACT ==> 2
   1. Trace #2: (FACT '1)
   2. Trace #2-1: (FACT '0)
   2. Trace #2-1: FACT ==> 1
   1. Trace #2: FACT ==> 1
   (2 1)

> how about adding a "bindings" slot to tracer that would allow Basile to
implement
> these IDs on his own?

If such an option is sufficient for implementing this output with IDs,
then I'm
in favour of it.

----------------------------------------------------------------------

Comment By: Sam Steingold (sds)
Date: 2007-10-11 22:28

Message:
Logged In: YES 
user_id=5735
Originator: NO

Bruno, if you are so unhappy about my solution, how about adding a
"bindings" slot to tracer that would allow Basile to implement these IDs on
his own?

----------------------------------------------------------------------

Comment By: Sam Steingold (sds)
Date: 2007-10-09 23:29

Message:
Logged In: YES 
user_id=5735
Originator: NO

>| The rationale is that in real debugging sessions, finding quickly
(e.g.
>| with emacs Ctrl-R) the beginning trace matching the ending trace would
>| be much easier.

>This is not true. The #nnn numbers buy you nothing for this purpose.
>If, for example, you're at the line
>   2. Trace: FACT ==> 2
>and search where it came from, just search backward for "2. Trace:".
>In Emacs: Ctrl-R 2. Trace:

this is the same as the message from 2007-10-06 04:52.
"2" is call depth, not the call id.
there could be many different calls with the same call depth in the same
emacs buffer, 
but only one call of a given function with the given call count.

if you want the variable, you can have it, of course.

----------------------------------------------------------------------

Comment By: Bruno Haible (haible)
Date: 2007-10-09 23:23

Message:
Logged In: YES 
user_id=5923
Originator: NO

| The rationale is that in real debugging sessions, finding quickly (e.g.
| with emacs Ctrl-R) the beginning trace matching the ending trace would
be
| much easier.

This is not true. The #nnn numbers buy you nothing for this purpose.
If, for example, you're at the line

   2. Trace: FACT ==> 2

and search where it came from, just search backward for "2. Trace:".
In Emacs: Ctrl-R 2. Trace:

The added numbers are therefore just clutter. They confuse the user.
Better get away without them. Simpler output is easier to understsnd by
the user.

I have no objection to this code being available in clisp if some
particular variable,
say *TRACE-IDENTIFY-CALLS*, is set. But it should be off by default.

----------------------------------------------------------------------

Comment By: Sam Steingold (sds)
Date: 2007-10-09 22:02

Message:
Logged In: YES 
user_id=5735
Originator: NO

Thanks for the suggestion - it has been just implemented and
checked into the CVS repository, and will be available in the next
release.
If you cannot wait for the next release, you can get the latest
development sources from the CVS and compile them yourself.
Please be aware that the development sources are not stable and
might not even compile on your machine.
You should report any problems you encounter with the CVS sources
to the <clisp-devel> mailing list, not to the <clisp-list>.
If you use the CVS sources, you should read <clisp-devel>
since the CVS log goes there.

----------------------------------------------------------------------

Comment By: Basile STARYNKEVITCH (bstarynk)
Date: 2007-10-09 07:51

Message:
Logged In: YES 
user_id=505600
Originator: YES

The patch trace-1808029-call-count.diff works great for me.

I hope it will be incorporated.

A big thanks!

----------------------------------------------------------------------

Comment By: Basile STARYNKEVITCH (bstarynk)
Date: 2007-10-09 07:51

Message:
Logged In: YES 
user_id=505600
Originator: YES

The patch trace-1808029-call-count.diff works great for me.

I hope it will be incorporated.

A big thanks!

----------------------------------------------------------------------

Comment By: Sam Steingold (sds)
Date: 2007-10-08 22:38

Message:
Logged In: YES 
user_id=5735
Originator: NO

please try the appended patch.
File Added: trace-1808029-call-count.diff

----------------------------------------------------------------------

Comment By: Basile STARYNKEVITCH (bstarynk)
Date: 2007-10-08 19:20

Message:
Logged In: YES 
user_id=505600
Originator: YES

SDS suggestion of using :pre and :post to trace does not seems to work
easily, since I want to print the call counter (i.e. its value on function
entry) at return (when the function has been recursively called many times
so the counter has increased). In other words, the trace macro has to
expand each traced function to something like
   (let ( (local-trace-counter (incf global-trace-counter)) )
     ;;; the entering trace message using local-trace-counter
     ;;; the function to be traced
     ;;; the exiting trace message using local-trace-counter
  )

----------------------------------------------------------------------

Comment By: Sam Steingold (sds)
Date: 2007-10-08 18:55

Message:
Logged In: YES 
user_id=5735
Originator: NO

you already can accomplish something like that using the trace arguments
:pre & :post, see
http://clisp.cons.org/impnotes/environment-dict.html#trace

----------------------------------------------------------------------

Comment By: Basile STARYNKEVITCH (bstarynk)
Date: 2007-10-08 18:38

Message:
Logged In: YES 
user_id=505600
Originator: YES

Sorry for putting a simplisitc example. I really meant a call counter, so
that in the same process, if later on, after having traced (fact 3) like
above, (fact 2) is called again, it would give
(fact 2)
1. Trace #5: (FACT '2)
2. Trace #6: (FACT '1)
3. Trace #7: (FACT '0)
3. Trace #7: FACT ==> 1
2. Trace #6: FACT ==> 2
1. Trace #5: FACT ==> 6

I'm actually coding a tiny Lisp to C compiler which I sort of bootstrap
with Clisp, so that the above feature would be helpful. See my GCC Summit
2007 paper (on my home page http://starynkevitch.net/Basile/ )

Thanks for reading -- Basile Starynkevitch

----------------------------------------------------------------------

Comment By: Sam Steingold (sds)
Date: 2007-10-08 16:21

Message:
Logged In: YES 
user_id=5735
Originator: NO

well, strictly speaking the number in the first column is the stack depth,
not call counter.

----------------------------------------------------------------------

Comment By: szergling (szergling)
Date: 2007-10-06 10:52

Message:
Logged In: YES 
user_id=1630354
Originator: NO

There's numbers along the first column already. For what you want, won't
(i)search-forward-regexp work? You may for example search for C-M-s ^4

I think some Lisps, or maybe even clisp2-41? (can't check at the moment)
indent the trace output according to stack depth, that could work...

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=351355&aid=1808029&group_id=1355