[Rd] execution time of .packages

[Romain Francois]

Prof Brian Ripley wrote:
> The caching is in the disc system: you need to find and read the 
> package metadata for every package.  AFAIK it is not easy to flush the 
> disc cache, but quite easy to overwrite it with later reads.  (Google 
> for more info.)
Thanks for the info, I'll try to find my way with these directions.

> If you are not concerned about validity of the installed packages you 
> could skip the tests and hence the reads.
>
> Your times are quite a bit slower than mine, so a faster disc system 
> might help.  Since my server has just been rebooted (for a new 
> kernel), with all of CRAN and most of BioC I get
>
>> system.time( packs <- .packages( all = T ) )
>    user  system elapsed
>   0.518   0.262  25.042
>> system.time( packs <- .packages( all = T ) )
>    user  system elapsed
>   0.442   0.080   0.522
>> length(packs)
> [1] 2096
>
> There's a similar issue when installing packages: the Perl code reads 
> the indices from every visible package to resolve links, and that can 
> be slow the first time.
>
>
> On Tue, 3 Mar 2009, Romain Francois wrote:
>
>> Hello,
>>
>> The first time in a session I call .packages( all.available = T ), it 
>> takes a long time (I have many packages installed from CRAN):
>>
>>> system.time( packs <- .packages( all = T ) )
>> user  system elapsed
>> 0.738   0.276  43.787
>>
>> When I call it again, the time is now much reduced, so there must be 
>> some caching somewhere. I would like to try to reduce the  time it 
>> takes the first time, but I have not been able to identify where the 
>> caching takes place, and so how I can remove it to try to improve the 
>> running time without the caching. Without this, I have to restart my 
>> computer each time to vanish the caching to test a new version of the 
>> function (this is not going to happen)
>>
>> Here is the .packages function, I am suspicious about this part : 
>> "ans <- c(ans, nam)" which grows the ans vector each time a suitable 
>> package is found, this does not sound right.
>
> It's OK as there are only going to be ca 2000 packages.  Try profiling 
> this: .readRDS and grepl take most of the time.
I usually do not trust the result of the profiler when a for loop is 
involved, as it tends to miss the point (or maybe I am).

Consider this script below, the profiler reports 0.22 seconds when the 
actual time spent is about 6 seconds,  and would blame rnorm as the 
bottleneck when the inefficiency is in with growing the data structure.

Rprof( )
x <- numeric( )
for( i in 1:10000){
  x <- c( x, rnorm(10) )
}
Rprof( NULL )
print( summaryRprof( ) )

$ time Rscript --vanilla profexample.R
$by.self
        self.time self.pct total.time total.pct
"rnorm"      0.22      100       0.22       100

$by.total
        total.time total.pct self.time self.pct
"rnorm"       0.22       100      0.22      100

$sampling.time
[1] 0.22

real    0m6.164s
user    0m5.156s
sys     0m0.737s

$ time Rscript --vanilla -e "rnorm(10)"
 [1]  0.836411851  1.762081444  1.076305644  2.063515383  0.643254750
 [6]  1.698620443 -1.774479062 -0.432886214 -0.007949533  0.284089832

real    0m0.224s
user    0m0.187s
sys     0m0.024s


Now, if i replace the for loop with a similar silly lapply construct, 
profiler tells me a rather different story:

Rprof( )
x <- numeric( )
y <- lapply( 1:10000, function(i){
    x <<- c( x, rnorm(10) )
    NULL
} )
Rprof( NULL )
print( summaryRprof( ) )

$ time Rscript --vanilla prof2.R
$by.self                                           
         self.time self.pct total.time total.pct   
"FUN"         6.48     96.1       6.68      99.1   
"rnorm"       0.20      3.0       0.20       3.0
"lapply"      0.06      0.9       6.74     100.0

$by.total
         total.time total.pct self.time self.pct
"lapply"       6.74     100.0      0.06      0.9
"FUN"          6.68      99.1      6.48     96.1
"rnorm"        0.20       3.0      0.20      3.0

$sampling.time
[1] 6.74

real    0m8.352s
user    0m4.762s
sys     0m2.574s

Or let us wrap the for loop of the first example in a function:

Rprof( )
x <- numeric( )
ffor <- function(){
    for( i in 1:10000){
      x <- c( x, rnorm(10) )
    }
}
ffor()
Rprof( NULL )
print( summaryRprof( ) )
  

$ time Rscript --vanilla prof3.R
$by.self
        self.time self.pct total.time total.pct
"ffor"        5.4     96.4        5.6     100.0
"rnorm"       0.2      3.6        0.2       3.6

$by.total
        total.time total.pct self.time self.pct
"ffor"         5.6     100.0       5.4     96.4
"rnorm"        0.2       3.6       0.2      3.6

$sampling.time
[1] 5.6

real    0m6.379s
user    0m5.408s
sys     0m0.717s



Maybe I get this all wrong, maybe the global assignment operator is 
responsible for some of the time in the second example. But how can I 
analyse the result of profiler in the first example when it seems to 
only be interested in the .22 seconds when I want to know what is going 
on with the rest of the time.

Is it possible to treat "for" as a function when writing the profiler 
data so that I can trust it more ?

Romain

-- 
Romain Francois
Independent R Consultant
+33(0) 6 28 91 30 30
http://romainfrancois.blog.free.fr