#33 trace with call counters

closed-accepted
5
2007-10-12
2007-10-05
No

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.

Discussion

  • szergling

    szergling - 2007-10-06

    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...

     
  • Sam Steingold

    Sam Steingold - 2007-10-08

    Logged In: YES
    user_id=5735
    Originator: NO

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

     
  • Sam Steingold

    Sam Steingold - 2007-10-08
    • labels: --> Extend ANSI CL
     
  • Basile STARYNKEVITCH

    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

     
  • Basile STARYNKEVITCH

    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
    )

     
  • Sam Steingold

    Sam Steingold - 2007-10-08

    Logged In: YES
    user_id=5735
    Originator: NO

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

     
  • Basile STARYNKEVITCH

    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!

     
  • Basile STARYNKEVITCH

    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!

     
  • Sam Steingold

    Sam Steingold - 2007-10-09

    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.

     
  • Sam Steingold

    Sam Steingold - 2007-10-09
    • summary: better trace (with call counters) --> trace with call counters
    • status: open --> closed-accepted
     
  • Bruno Haible

    Bruno Haible - 2007-10-09

    Logged In: YES
    user_id=5923
    Originator: NO

    The rationale is that in real debugging sessions, finding quickly (e.g.
    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.

     
  • Sam Steingold

    Sam Steingold - 2007-10-09

    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.

     
  • Sam Steingold

    Sam Steingold - 2007-10-11

    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?

     
  • Bruno Haible

    Bruno Haible - 2007-10-11

    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.

     
  • Sam Steingold

    Sam Steingold - 2007-10-11

    Logged In: YES
    user_id=5735
    Originator: NO

    >> 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.

    I will leave this to Basile - if he wants
    this patch to appear in the next release,
    he has to fight for it. :-)

    >> It is not welcome usually that two executions of the same form
    >> from a REP loop yield different output.

    how about prompt number? :-)

    >>>> 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.

    OK, so -- do I need to invalidate bytecodes
    if I add a slot to tracer?

     
  • Sam Steingold

    Sam Steingold - 2007-10-11
    • assigned_to: nobody --> sds
    • status: closed-accepted --> open-accepted
     
  • Sam Steingold

    Sam Steingold - 2007-10-12
    • status: open-accepted --> closed-accepted
     

Log in to post a comment.