From braunm at MIT.EDU  Sat May 26 03:21:04 2007
From: braunm at MIT.EDU (Michael Braun)
Date: Fri, 25 May 2007 21:21:04 -0400
Subject: [Rd] R scripts slowing down after repeated called to
	compiled	code
In-Reply-To: <200705251929.56159.vdergachev@rcgardis.com>
References: <1180134776.6736.15.camel@braunm1>
	<200705251929.56159.vdergachev@rcgardis.com>
Message-ID: <1180142464.7276.17.camel@braunm1>


Vladimir:

Thanks for your response.  I have done as you requested (with a smaller
dataset--the patterns are still there).  Here is the gc()-laden output.

I don;t fully understand the meaning of all parts of these reports.  But
it does look like the number of objects grows (and it grows faster on
the larger, slower problem).  But how can I use this information to
narrow down the cause?

As far as your other suggestions, my PROTECTs and UNPROTECTs are all
balanced (I'd get a stack imbalance if they weren't).  One thing I am
doing is duplicating the SEXP's that are passed from R, and working with
the copies.  I unprotect the copies at the end of the function.  There
are other, various VECTOR_ELT's in my code.

So where do I go from there?

Michael



Dataset  B06   Iteration:   1
Garbage collection 67 = 33+9+25 (level 2) ...
778324 cons cells free (42%)
32.4 Mbytes of heap free (28%)

Dataset  B06   Iteration:   2
Garbage collection 92 = 52+11+29 (level 2) ...
778303 cons cells free (42%)
43.9 Mbytes of heap free (34%)

Dataset  B06   Iteration:   3
Garbage collection 112 = 69+12+31 (level 2) ...
778303 cons cells free (42%)
43.9 Mbytes of heap free (34%)

Dataset  B06   Iteration:   4
Garbage collection 126 = 79+13+34 (level 2) ...
778303 cons cells free (42%)
50.7 Mbytes of heap free (38%)

Dataset  B06   Iteration:   5
Garbage collection 139 = 89+14+36 (level 2) ...
778303 cons cells free (42%)
50.7 Mbytes of heap free (38%)

Dataset  B06   Iteration:   6
Garbage collection 149 = 95+15+39 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   7
Garbage collection 157 = 101+15+41 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   8
Garbage collection 165 = 107+15+43 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   9
Garbage collection 173 = 112+16+45 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   10
Garbage collection 181 = 118+16+47 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   11
Garbage collection 188 = 123+16+49 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   12
Garbage collection 195 = 128+16+51 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   13\
Garbage collection 202 = 132+17+53 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)

Dataset  B06   Iteration:   14
Garbage collection 209 = 137+17+55 (level 2) ...
778303 cons cells free (42%)
58.0 Mbytes of heap free (41%)





On Fri, 2007-05-25 at 19:29 -0400, Vladimir Dergachev wrote:
> On Friday 25 May 2007 7:12 pm, Michael Braun wrote:
> > Thanks in advance to anyone that might be able to help me with this
> >
> > Also, it is not just the compiled call that slows down.  EVERYTHING
> > slows down, even those that consist only of standard R functions.  The
> > time for each of these function calls is roughly proportional to the
> > time of the .Call to the C function.
> >
> > Another observation is that when I terminate the algorithm, do a rm
> > (list=ls()), and then a gc(), not all of the memory is returned to the
> > OS.  It is not until I terminate the R session that I get all of the
> > memory back.  In my C code, I am not doing anything to de-allocate the
> > SEXP's I create, relying on the PROTECT/UNPROTECT mechanism instead (is
> > this right?).
> >
> > I spent most of the day thinking I have a memory leak, but that no
> > longer appears to be the case.  I tried using Rprof(), but that only
> > gives me the aggregated relative time spent in each function (more than
> > 80% of the time, it's in the .Call).
> 
> One possibility is that you are somehow creating a lot of R objects (say by 
> calling assign() or missing UNPROTECT()) and this slows garbage collector 
> down. The garbage collector running time will grow with the number of objects 
> you have - their total size does not have to be large.
> 
> Could you try printing numbers from gc() call and checking whether the numbers 
> of allocated objects grow a lot ?
> 
>                           best
> 
>                             Vladimir Dergachev
> 
> >
> > So I'm stuck.  Can anyone help?
> >
> > Thanks,
> >
> > Michael
> 
> 
> The information contained in this transmission may contain privileged and confidential information. It is intended only for the use of the person(s) named above. If you are not the intended recipient, you are hereby notified that any review, dissemination, distribution or duplication of this communication is strictly prohibited. If you are not the intended recipient, please contact the sender by reply email and destroy all copies of the original message. 
> 
> 
-- 
Michael Braun
Assistant Professor of Marketing
MIT Sloan School of Management
One Amherst St., E40-169
Cambridge, MA 02142
(617) 253-3436
braunm at mit.edu



[Rd] R scripts slowing down after repeated called to compiled code
Michael Braun