User time and system time

[Douglas Bates]

I am running the R-0.62.0 snapshot on a Linux system.  This system has
128 Mb of real memory and almost never swaps.  I am trying to use
lme() on a very large example (7200 observations, 10 columns in the
fixed effects, 2 columns in the random effects).  We have the
optimization nicely tuned so that goes relatively quickly.  It seems,
though, that all the data manipulation steps before the optimization
are taking a rather long time.  I haven't compared on the same machine
but R is much slower - like an order of magnitude - than S-PLUS on
this problem.

It looks curious to me when I run system.time() on this that timing
vector shows almost no user time but a huge amount of system time.
 R> system.time(assign("fm2",
 +    lme(MathAch ~ MEANSES*CSES + Sector + CSES:Sector, ttt, ~ CSES | School,
 +        RML = TRUE )))
 iteration = 0
 Step:
 [1] 0 0 0
 Parameter:
 [1] 2.61400 0.16608 3.88195
 Function Value
 [1] 44964
 Gradient:
 [1] -0.014379 -0.143176 -0.646558

 iteration = 1
 Step:
 [1] 0.002888 0.028756 0.129857
 Parameter:
 [1] 2.61688 0.19483 4.01181
 Function Value
 [1] 44964
 Gradient:
 [1] -0.069529  0.539316  0.094097
 ... 
 iteration = 6
 Parameter:
 [1] 2.61636 0.17797 3.98709
 Function Value
 [1] 44964
 Gradient:
 [1] 8.3428e-06 1.3824e-04 3.1205e-04

 Relative gradient close to zero.
 Current iterate is probably solution.

 [1]   1.09 288.05 289.00   0.00   0.00

I can't really believe that it took only 1 second of user time and 288 
seconds of system time.  It didn't even do garbage collection in R (I
had gcinfo(T) set) and it wasn't swapping.

A call to proc.time() directly shows most of the time used is system
time.
 R> proc.time()
 [1]    16.30   577.01 13679.00     0.02     0.23

I looked at the code in src/unix/system.c and the structure seems
consistent.  Has anyone else tested system.time() extensively on a
Linux system?  Anyone have any ideas what might be going on?

Just for reference, this is a Debian GNU/Linux "hamm" system using
libc6.  I am running R with the options shown below. 
USER       PID %CPU %MEM  SIZE   RSS TTY STAT START   TIME COMMAND
bates    31073  3.8 41.1 54340 52620  p0 S    10:47   9:53 /usr/src/packages/r-base/r-base-0.62.0/bin/R.binary -v 40 -n 500000 

-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-
r-devel mailing list -- Read http://www.ci.tuwien.ac.at/~hornik/R/R-FAQ.html
Send "info", "help", or "[un]subscribe"
(in the "body", not the subject !)  To: r-devel-request@stat.math.ethz.ch
_._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._._