system.time question

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

system.time question

Thread (4 messages)