[R] system.time question

[William Dunlap]

Others have said what system time is, time spent in the kernel of the operating
system doing things on behalf of your program.   Also, switching between user
and system mode can be time consuming, so the number of system calls can
be important, even if each one takes little time.  I don't know how the time it
takes to switch is reported - is it user, system or just elapsed time.

In my experience, a big system time that is a red flag and you can usually get
rid of most of it.  Often, reducing the system time decreases the user time as
well.  In many cases it is due to opening files and writing to or reading from files.
E.g., define a function, f, that append a few lines to a file:
  f <- function (filename)  cat(file = filename, append = TRUE, 1:4, sep = "\n")
Use system.time to time it on a file in /tmp:
  > tf <- "/tmp/junk.txt"
  > unlink(tf) ; system.time(for(i in 1:10000)f(tf))
     user  system elapsed
    0.752   0.216   0.967
The system time is a quarter of the user time.  One way of reducing that time
is to open the file once, write to it many times, then close it.  (Opening a file
is time consuming because it needs to be found.)
  > unlink(tf) ; tfo <- file(tf, open="w") ; system.time(for(i in 1:10000)f(tfo)) ; close(tfo)
     user  system elapsed
    0.128   0.100   0.227
The system/user ratio is still high, but all the times are smaller.

Here is an example of the waiting for a resource problem that Brian Ripley mentioned.
I use the same function, f, but I use it on a file in my home directory, which is
on a file server.  (/tmp is of type 'tmpfs, which I think means it is not even on a disk.)
  > mf <- "/homes/bill/junk.txt"
  > unlink(mf) ; system.time(for(i in 1:10000)f(mf))
     user  system elapsed
    1.476   1.208  41.532
The huge elapsed time it due to the kernel waiting for the file server to find
/homes/bill/junk.txt, over and over again.  Open it once and the times are more
in line with using /tmp:
  > unlink(mf) ; mfo <- file(mf, open="w") ; system.time(for(i in 1:10000)f(mfo)) ; close(mfo)
     user  system elapsed
    0.140   0.044   0.186

On Linux you can use the strace command to see what system calls R is making
while your program runs.  Get the process identifier from Sys.getpid() and run strace
in a different window.   E.g.,

% strace -T -p 24197 | & head -100
... lots of repetitions of the following sequence:
open("/homes/bill/junk.txt", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3 <0.003782>
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0 <0.000037>
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9ffae4b000 <0.000038>
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0 <0.000078>
lseek(3, 0, SEEK_SET)                   = 0 <0.000011>
write(3, "1", 1)                        = 1 <0.000087>
write(3, "\n", 1)                       = 1 <0.000088>
write(3, "2", 1)                        = 1 <0.000014>
write(3, "\n", 1)                       = 1 <0.000010>
write(3, "3", 1)                        = 1 <0.000011>
write(3, "\n", 1)                       = 1 <0.000010>
write(3, "4", 1)                        = 1 <0.000010>
write(3, "\n", 1)                       = 1 <0.000009>
close(3)                                = 0 <0.001938>
munmap(0x7f9ffae4b000, 65536)           = 0 <0.000032>
open("/homes/bill/junk.txt", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3 <0.003711>
...

The times are shown in <>.

Bill Dunlap
Spotfire, TIBCO Software
wdunlap tibco.com


> -----Original Message-----
> From: r-help-bounces at r-project.org [mailto:r-help-bounces at r-project.org] On Behalf
> Of Mark Leeds
> Sent: Saturday, October 20, 2012 9:16 AM
> To: R help
> Subject: [R] system.time question
> 
> Hi : I looked at the help for system.time but I still have the following
> question. Can someone explain the output following output
> of system.time :
> 
>  user          system      elapsed
> 12399.681  5632.352   56935.647
> 
> Here's my take based on the fact that I was doing ps -aux | grep R off and
> on and the total amount of CPU minutes that
> got allotted before the job ended was about 5 hours and the total actual
> time that the job took was about 15 hours.
> 
> Does elapsed = total actual time job taken ? That seems to be the case or a
> strange coincidence.
> 
> Does user + system = CPU time from ps -aux | grep R ? That seems to be the
> case also or a weird coincidence.
> 
> Finally, why can't the CPU get a higher percentage ? It's seems like it's
> always around 30% which would make sense since
> 5 is ~ 30% of 15 hours.
> 
> Also, assuming my take above is correct, when talking about timing of
> algorithms, in this case, does one say the job took 5 hours or 15 hours ?
> I'm trying to see how fast an algorithm is compared to others and I'm not
> sure what the standard is.  I'm on fedora 16.0 and using R 2.15. Thanks.
> 
> 	[[alternative HTML version deleted]]
> 
> ______________________________________________
> R-help at r-project.org mailing list
> https://stat.ethz.ch/mailman/listinfo/r-help
> PLEASE do read the posting guide http://www.R-project.org/posting-guide.html
> and provide commented, minimal, self-contained, reproducible code.