Skip to content

system.time question

4 messages · Mark Leeds, Jeff Newmiller, Brian Ripley +1 more

Jeff Newmiller
# 
You asked several questions.
Elapsed: yes
User + System = CPU: yes
Finally: You have to look at the load and/or cpu core count. Unless you setup your code to take advantage of multiple cores, R runs on a single core.
Also: Do you really need to ask that question?

---------------------------------------------------------------------------
Jeff Newmiller                        The     .....       .....  Go Live...
DCN:<jdnewmil at dcn.davis.ca.us>        Basics: ##.#.       ##.#.  Live Go...
                                      Live:   OO#.. Dead: OO#..  Playing
Research Engineer (Solar/Batteries            O.O#.       #.O#.  with
/Software/Embedded Controllers)               .OO#.       .OO#.  rocks...1k
--------------------------------------------------------------------------- 
Sent from my phone. Please excuse my brevity.
Mark Leeds <markleeds2 at gmail.com> wrote:

            

      
      
      
    

        

      
      
    

  
  


  


      

    

    

      
      

        


  

        

      Brian Ripley
    

    

      
      #
    

  


  

      
On 20/10/2012 17:16, Mark Leeds wrote:

            

      
      
      
    

        
Yes, the help page can, via ?proc.time.  As it says, it depends on the OS

            

      
      
      
    

        
On Fedora Linux, yes.  Not in general (and what ps gives is pretty 
OS-specific: for example, does it include time from child processes or 
not -- system.time should but the OS calls used do not always do so, I 
find less reliably so in Fedora 16 than 14).

            

      
      
      
    

        
Many, many reasons.  Most likely

- other things are running, and some of them have a higher priority, or 
equal or lower priority and get lots of time slices ....

- R the process is waiting for resources, such as memory, discs, network 
access ....

            

      
      
      
    

        
It depends on the purpose.  CRAN's check farm cares most about CPU 
usage: someone waiting for results cares about elapsed time.

            

      
      
      
    

        

      
      
    

        

  
    

      
      
    

  


  


      

    

    
1 day later

    

      
      

        


  

        

      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