[Rd] .doTrace problem with eval.parent(substitute(expr)) vs. lazy evaluation of expr

[William Dunlap]

Here are a couple of problems with the use of
eval.parent(substitute(expr))
instead of just lazily evaluating expr in the .doTrace function used by
trace.

(a) In S+ I sometimes use trace() to see how long a function takes
to run with a tracer expression the saves the start time and calls
on.exit to report the difference between the start and end times
when the trace function ends.  E.g.,

> trace(unix, Quote({START<-proc.time();on.exit(cat(command, "took",
proc.time()-START, "\n"))}))
> unix("sleep 4") # like R's system()
On entry: sleep 4 took 0 0 4.02000000000001 0 0.01
character(0)

This trick fails in R (2.10.0 svn 48672):

   > trace(system, Quote({START<-proc.time();on.exit(cat(command,
"took", proc.time()-START, "\n"))}))
   Tracing function "system" in package "base"
   [1] "system"
   > system("sleep 4")
   Tracing system("sleep 4") on entry
   sleep 4 took 0 0 0 0 0   
   [4 second pause before the next prompt]

If I change .doTrace by changing its
        exprObj <- substitute(expr)
        eval.parent(exprObj)
to just
        expr # evaluate in caller's environment by lazy evaluation
then the on.exit works as I wished it to.  I think the on.exit clause
is being executed at the end of eval.parent() instead of at the end of
the caller of .doTrace (put print(sys.calls()) into the on.exit to see
the evidence).

(b) Another thing I'm used to doing with trace() in S+ is to selectively
expand some of the arguments of the traced function (so I can see
its value instead of just its name), as in
   > trace(match,
Quote({CALL<-match.call();CALL$x<-paste(class(x),"(",length(x),")",sep="
");print(CALL)}))
   > for(x in list(factor(letters), 1:2, "c"))match(x,c("c","d","e")) 
   On entry: match(x = "character(26)", table = exclude)
   On entry: match(x = "character(26)", table = levels)
   On entry: match(x = "factor(26)", table = c("c", "d", "e"))
   On entry: match(x = "character(26)", table = table, nomatch =
nomatch, incomparables =
           incomparables)
   On entry: match(x = "integer(2)", table = c("c", "d", "e"))
   On entry: match(x = "character(1)", table = c("c", "d", "e"))
This fails in R
   > for(x in list(factor(letters), 1:2, "c"))match(x,c("c","d","e"))
   Tracing match(x, table, nomatch = 0L) on entry 
   Error in match.call() :
     unable to find a closure from within which 'match.call' was called
until I make that change to .doTrace
   > for(x in list(factor(letters), 1:2, "c"))match(x,c("c","d","e"))
   Tracing match(x, table, nomatch = 0L) on entry
   match(x = "character(1)", table = table, nomatch = 0L)
   Tracing match(levels, exclude) on entry
   match(x = "character(26)", table = exclude)
   Tracing match(x, levels) on entry
   match(x = "character(26)", table = levels)
   Tracing match(x, c("c", "d", "e")) on entry
   match(x = "factor(26)", table = c("c", "d", "e"))
   Tracing match(x, c("c", "d", "e")) on entry
   match(x = "integer(2)", table = c("c", "d", "e"))
   Tracing match(x, c("c", "d", "e")) on entry
   match(x = "character(1)", table = c("c", "d", "e"))

Would there be any harm in making this change to .doTrace?

I can avoid the on.exit problem by using both the tracer and exit
arguments to
trace:
   > trace(system, Quote(START<-proc.time()), exit=Quote(cat(command,
"took", proc.time()-START, "\n")))
   Tracing function "system" in package "base"
   [1] "system"
   > system("sleep 4")
   Tracing system("sleep 4") on entry
   Tracing system("sleep 4") on exit
   sleep 4 took 0.001 0.002 4.018 0.002 0.002
but I do miss the ability of the tracer to use match.call().

Are there other properties lost by using eval.parent(substitute(expr))
instead lazily evaluating expr?  Should eval.parent(substitute(expr))
try to mimic more closely the lazy evaluation of expr?

The patch I used for testing was
Index: src/library/base/R/methodsSupport.R
===================================================================
--- src/library/base/R/methodsSupport.R (revision 48762)
+++ src/library/base/R/methodsSupport.R (working copy)
@@ -87,8 +87,7 @@
               call <- paste(call[[1L]], "....")
             cat("Tracing", call, msg, "\n")
         }
-        exprObj <- substitute(expr)
-        eval.parent(exprObj)
+        expr # lazily evaluate expr
     }
     NULL
 }


Bill Dunlap
TIBCO Software Inc - Spotfire Division
wdunlap tibco.com