Skip to content

Suggestion for system.time()

5 messages · François Pinard, Seth Falcon

Original
François Pinard
# 
Hi, people.  A tiny suggestion for the system.time function.

Could the returned vector have names?  These could be like:

   c("User", "System", "Elapsed", "Sub.User", "Sub.System")

That would then produce self-documenting output.
Seth Falcon
# 
Fran?ois Pinard <pinard at iro.umontreal.ca> writes:
Here's a function you could try.  It names the result as you
suggested.  It also can be nested, which system.time cannot, because
it uses on.exit without specifying add=TRUE.

timeit <- function (expr, gcFirst = TRUE) 
{
    nms <- c("User", "System", "Elapsed", "Sub.User", "Sub.System")
    if (!exists("proc.time")) {
        ans <- rep(as.numeric(NA), 5)
        names(ans) <- nms
        return(ans)
    }
    loc.frame <- parent.frame()
    if (gcFirst) 
        gc(FALSE)
    expr <- substitute(expr)
    time <- proc.time()
    show_time <- function() {
        t <- proc.time() - time
        names(t) <- nms
        cat("Timing stopped at:\n")
        print(t)
        t 
    }
    tryCatch(eval(expr, envir = loc.frame),
             error=function(e) {
                 msg <- paste("Error in", deparse(conditionCall(e)),
                              ":", conditionMessage(e), "\n")
                 cat(msg)
             })
    show_time()
}


## Examples
Timing stopped at:
      User     System    Elapsed   Sub.User Sub.System 
     0.007      0.001      0.008      0.000      0.000
User     System    Elapsed   Sub.User Sub.System 
     0.007      0.001      0.008      0.000      0.000 

## Nested calls.  I dunno, could be useful in some debugging 
## situations *shrug*
Timing stopped at:
      User     System    Elapsed   Sub.User Sub.System 
     0.012      0.002      0.014      0.000      0.000 
Timing stopped at:
      User     System    Elapsed   Sub.User Sub.System 
     0.090      0.003      0.146      0.000      0.000
User     System    Elapsed   Sub.User Sub.System 
     0.090      0.003      0.146      0.000      0.000 


## With an error
Error in plot(foobarbaz) : object "foobarbaz" not found 
Timing stopped at:
      User     System    Elapsed   Sub.User Sub.System 
     0.002      0.000      0.038      0.000      0.000
User     System    Elapsed   Sub.User Sub.System 
     0.002      0.000      0.038      0.000      0.000
François Pinard
# 
[Seth Falcon]
Thanks, Seth.  Your code could be useful, I'm saving it. :-)

Just to be clear, my suggestion was more thought as a small benefit for 
the community of R users, rather than for myself alone.
Seth Falcon
# 
Fran?ois Pinard <pinard at iro.umontreal.ca> writes:
You make it sound like that code is going to mature like a wine.  I'd
say, if it isn't useful now, it will be less useful later, but hey,
disk space is cheap :-D
That's what I understood.  I bothered to post some code because I
agree and saw a couple of small ways to improve system.time: add
names, allow nesting, and compute the time once instead of twice[*].
Perhaps others will agree and consider a change.

Best,

+ seth


[*] system.time computes the elapsed time twice: once when running the
on.exit hook, which gets called explicitly (!), and once for the
return value.  Here's the relevant lines:

    on.exit(cat("Timing stopped at:", proc.time() - time, "\n"))  ## once
    eval(expr, envir = loc.frame)
    new.time <- proc.time()
    on.exit()
    new.time - time                                               ## twice
François Pinard
# 
[Seth Falcon]
:-) :-).  The truth is that it's _me_, and not the saved code, which is 
slowly maturing.  More time goes, more I become able to appreciate code 
and ideas.

I'm started in a long journey that should lead me in various corners of 
R and statistics.  There are flurry, plenty of these corners.  While 
most of them are still opaque for me, I begin to see tiny spots of 
transparency here and there, yet only after having paid many visits :-).
All in all, the whole experience is intriguing, and still passionating.