From: Bruno H. <br...@cl...> - 2004-10-21 11:10:06
|
Hi, This looks like a bug: Traced functions sometimes produce no traces although they are called. ===================== step 1: define a function and trace it ================= * (defun hypot (x y) (sqrt (+ (* x x) (* y y)))) HYPOT * (trace hypot) (HYPOT) ============================ step 2: call it =============================== * (hypot 3 4) 0: (HYPOT 3 4) 0: HYPOT returned 5.0 5.0 ================== step 3: call it through funcall, apply ================== * (funcall #'hypot 3 4) 5.0 * (apply #'hypot '(3 4)) 5.0 ============================================================================= So apparently ANSI CL 3.1.2.1.2.3. is violated. But this is not all. Here are a few more interactions that left me stunned. Confused. Completely lost. ==================== step 4: print the traced function ====================== * #'hypot #<FUNCTION HYPOT> ==================== step 5: assign it to two global variables ============== * (setq a * b #'hypot) ; in: LAMBDA NIL ; (SETQ A * B #'HYPOT) ; ==> ; (SETQ A *) ; ; caught WARNING: ; undefined variable: A ; ==> ; (SETQ B #'HYPOT) ; ; caught WARNING: ; undefined variable: B ; ; caught WARNING: ; These variables are undefined: ; A B ; ; compilation unit finished ; caught 3 WARNING conditions #<FUNCTION "CLOSURE" {9047265}> ============================================================================= This is even more fishy: the same form #'hypot evaluates to two different results, depending whether inside (setq ...) or not!! ============ step 6: verify the two functions are really different ========== * (eq a b) NIL * (funcall a 3 4) 5.0 * (funcall b 3 4) 0: (HYPOT 3 4) 0: HYPOT returned 5.0 5.0 ============================================================================= So it looks like the first one is the untraced function, the second one the traced one. ================= step 7: untrace the function and repeat =================== * (untrace hypot) T * (funcall a 3 4) 5.0 * (funcall b 3 4) 0: (HYPOT 3 4) 5.0 ============================================================================= But now b prints traces only on function entry, not on function exit?!??!?? Bruno PS: Another funny effect you get by doing (trace identity). |
From: Christophe R. <cs...@ca...> - 2004-10-21 11:52:20
|
Bruno Haible <br...@cl...> writes: > [ snipping the meat of your report -- but let me clear this up for you ] > But this is not all. Here are a few more interactions that left me stunned. > Confused. Completely lost. > > ==================== step 4: print the traced function ====================== > * #'hypot > > #<FUNCTION HYPOT> > ==================== step 5: assign it to two global variables ============== ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ No. "Invoke undefined behaviour" might be closer to what you actually did. > * (setq a * b #'hypot) > ; in: LAMBDA NIL > ; (SETQ A * B #'HYPOT) > ; ==> > ; (SETQ A *) > ; > ; caught WARNING: > ; undefined variable: A > > ; ==> > ; (SETQ B #'HYPOT) > ; > ; caught WARNING: > ; undefined variable: B > > ; > ; caught WARNING: > ; These variables are undefined: > ; A B > ; > ; compilation unit finished > ; caught 3 WARNING conditions We don't give these warnings out for nothing: what you have done is indeed undefined behaviour. If you were to do (proclaim '(special a b)) first, you would get the answer you expect. > PS: Another funny effect you get by doing (trace identity). This is also invoking undefined behaviour: see clhs 11.1.2.1.2. While it might be nice to offer tracing of CL functions, it's not required to work, and I hope it's relatively clear why it can't always work -- when the system itself uses the function being traced to implement the tracing. Cheers, Christophe |
From: Bruno H. <br...@cl...> - 2004-10-21 14:01:36
|
Christophe Rhodes wrote: > If you were to do > (proclaim '(special a b)) > first, you would get the answer you expect. Indeed, but it is surprising as well that the value of #'hypot depends on whether I've already defvar'ed the variable I assign it to. > > PS: Another funny effect you get by doing (trace identity). > > This is also invoking undefined behaviour: ... > when the system itself uses the function being traced to implement the > tracing. Are you sure this is the problem? On my slow machine, it takes ca. 1.5 seconds for each output line to come out, and when I interrupt with Ctrl-C I get a stack trace that does not indicate recursion; rather the time seems to be spent in compute-lra-data-from-pc. 6: ("foreign function: component_ptr_from_pc") 7: ("foreign function: #x54A1127") 8: (SB-DI::COMPUTE-LRA-DATA-FROM-PC 1 #.(SB-SYS:INT-SAP #X01DF3643))[:EXTERNAL] 9: (SB-DI::COMPUTE-CALLING-FRAME 3 #.(SB-SYS:INT-SAP #X4037B630) #.(SB-SYS:INT-SAP #X01DF3643) NIL)[:EXTERNAL] 10: (SB-DEBUG::TRACE-CALL #<SB-DEBUG::TRACE-INFO IDENTITY>) 11: (SB-INT:EVAL-IN-LEXENV 2 (SB-DEBUG::TRACE-CALL '#<SB-DEBUG::TRACE-INFO IDENTITY>) #S(SB-KERNEL:LEXENV :FUNS NIL :VARS NIL :BLOCKS NIL :TAGS NIL :TYPE-RESTRICTIONS NIL :LAMBDA NIL :CLEANUP NIL ...))[:EXTERNAL] 12: ("varargs entry for SB!IMPL::ENCAPSULATION" #\t) 13: (SB-KERNEL:%FIND-POSITION 7 #\Newline " 0: IDENTITY returned #\\T " NIL 0 27 #<FUNCTION "CLOSURE" {901B455}> #<FUNCTION "top level local call EQL" {100FC4D}>)[:EXTERNAL] 14: (SB-IMPL::FD-SOUT 4 #<FILE-STREAM for "standard output" {9002029}> " 0: IDENTITY returned #\\T " 0 27)[:EXTERNAL] 15: (SB-IMPL::%WRITE-STRING 4 " 0: IDENTITY returned #\\T " #<FILE-STREAM for "standard output" {9002029}> 0 27)[:EXTERNAL] 16: ("varargs entry for top level local call WRITE-STRING" " 0: IDENTITY returned #\\T " #<FILE-STREAM for "standard output" {9002029}> :START 0 :END 27) 17: (SB-IMPL::%WRITE-STRING 4 " 0: IDENTITY returned #\\T " #<SYNONYM-STREAM :SYMBOL SB-SYS:*STDOUT* {500DF59}> 0 27)[:EXTERNAL] 18: (SB-IMPL::ANSI-STREAM-WRITE-SEQUENCE 4 " 0: IDENTITY returned #\\T " #<SYNONYM-STREAM :SYMBOL SB-SYS:*STDOUT* {500DF59}> 0 NIL)[:EXTERNAL] 19: (WRITE-SEQUENCE 2 " 0: IDENTITY returned #\\T " #<SYNONYM-STREAM :SYMBOL SB-SYS:*STDOUT* {500DF59}>)[:EXTERNAL] 20: ("#'(LAMBDA (SB-DEBUG::FRAME SB-DEBUG::BPT SB-DEBUG:*TRACE-VALUES* ...) (DECLARE #) ...)" #<SB-DI::COMPILED-FRAME SB-INT:EVAL-IN-LEXENV> #<unavailable argument> (#\T) NIL) 21: (SB-DEBUG::TRACE-CALL #<SB-DEBUG::TRACE-INFO IDENTITY>) 22: (SB-INT:EVAL-IN-LEXENV 2 (SB-DEBUG::TRACE-CALL '#<SB-DEBUG::TRACE-INFO IDENTITY>) #S(SB-KERNEL:LEXENV :FUNS NIL :VARS NIL :BLOCKS NIL :TAGS NIL :TYPE-RESTRICTIONS NIL :LAMBDA NIL :CLEANUP NIL ...))[:EXTERNAL] 23: ("varargs entry for SB!IMPL::ENCAPSULATION" #\T) 24: (SB-KERNEL:%FIND-POSITION 7 #\Newline "(IDENTITY)" NIL 0 10 #<FUNCTION "CLOSURE" {901B455}> #<FUNCTION "top level local call EQL" {100FC4D}>)[:EXTERNAL] 25: (SB-IMPL::FD-SOUT 4 #<FILE-STREAM for "standard output" {9002029}> "(IDENTITY)" 0 10)[:EXTERNAL] 26: (SB-IMPL::%WRITE-STRING 4 "(IDENTITY)" #<FILE-STREAM for "standard output" {9002029}> 0 10)[:EXTERNAL] 27: ("varargs entry for top level local call WRITE-STRING" "(IDENTITY)" #<FILE-STREAM for "standard output" {9002029}> :START 0 :END 10) 28: (SB-IMPL::%WRITE-STRING 4 "(IDENTITY)" #<SYNONYM-STREAM :SYMBOL SB-SYS:*STDOUT* {500DF59}> 0 10)[:EXTERNAL] 29: ("varargs entry for top level local call WRITE-STRING" "(IDENTITY)" #<SYNONYM-STREAM :SYMBOL SB-SYS:*STDOUT* {500DF59}> :START 0 :END 10) 30: (SB-PRETTY:OUTPUT-PRETTY-OBJECT 2 (IDENTITY) #<SYNONYM-STREAM :SYMBOL SB-SYS:*STDOUT* {500DF59}>)[:EXTERNAL] 31: ("hairy arg processor for top level local call PRIN1" (IDENTITY) NIL) 32: (SB-IMPL::REPL-FUN 1 NIL)[:EXTERNAL] 33: ("#'(LAMBDA NIL (HANDLER-BIND # #))") 34: ("XEP for #'(LAMBDA NIL (HANDLER-BIND # #))" 0)[:EXTERNAL] 35: (SB-IMPL::%WITH-REBOUND-IO-SYNTAX 1 #<FUNCTION "CLOSURE" {9007B7D}>)[:EXTERNAL] 36: (SB-IMPL::TOPLEVEL-REPL 1 NIL)[:EXTERNAL] 37: (SB-IMPL::TOPLEVEL-INIT 0)[:EXTERNAL] 38: ("FLET SB!IMPL::RESTART-LISP") Either there is only one call to COMPUTE-CALLING-FRAME per output line, then why does it take 1.5 seconds? Or there are many more calls to COMPUTE-CALLING-FRAME, because IDENTITY is a frequently used function, then most of these calls are useless because they produce no output; why are they performed then? Bruno |
From: Nikodemus S. <tsi...@cc...> - 2004-10-21 16:14:26
|
On Thu, 21 Oct 2004, Bruno Haible wrote: > This looks like a bug: Traced functions sometimes produce no traces although > they are called. Yes. There is a FIXME in fdefinition.lisp to the effect, though no actual BUGS entry. It seems to me that making fdefinition return the encapsulated function, but keeping (setf fdefinition) as is would be sufficient. I'm expecting that there will be places where this will violate assumptions, and where unencapsulated-fdefinition must be used instead -- but can anyone anticipate problems beyond that? I have a preliminay implementation of this done, plus reworking the encapsulation to use closures instead of special variables -- looking a bit like the Allegro fwrappers module def-fwrapper. Cheers, -- Nikodemus Schemer: "Buddha is small, clean, and serious." Lispnik: "Buddha is big, has hairy armpits, and laughs." |