[R] interpreting profiling output

[Kasper Daniel Hansen]

On Tue, Jul 27, 2004 at 09:12:56AM +0200, Peter Dalgaard wrote:
> [What did ess-help have to do with this?? Snipped from CC:]

This happens when posting in a hurry using a new mail client. Sorry. See 
below btw.

> Kasper Daniel Hansen <k.hansen at biostat.ku.dk> writes:
> 
> > Thanks to both of you for considering my question. I still have some
> > problems however. Consider the nnet.default function which uses the .C
> > interface. As 
> > > typeof(.C)
> > [1] "builtin"
> > I would guess - from my current understanding - that the time spent in
> > the C functions of nn.default are added to its self.time. Now look at
> > the output
> > 
> > > prof02.out$by.self[1:10,]
> >                   self.time self.pct total.time total.pct
> > nnet.default          33.32     11.2    2186.48      92.1
> > 
> > So nnet.default only used 33.3 on its C calls, but 2186 in total
> > time. From this I would guess that nnet.default - in my case - spends
> > its majority of time setting up the fit and postprocessing it (as this
> > is done by R functions which does not add to its self time). The
> > actual fit (which is done by the C functions) only takes very little
> > time. 
> > 
> > Looking further down the table I see
> > 
> >                   self.time self.pct total.time total.pct
> > as.integer            22.28      7.5      30.92       1.3
> > 
> > as.interger is basically a .Internal call - which ought not to be
> > recorded. But why does it then have such a "high" self.time?
> > 
> > And finally, if a program (such as mine) have a high discrepancy
> > between self.time and sampling.time, does this imply that the far
> > majority of time is spent in .Primitives which are of type special?
> 
> Hmm... You're using summaryRprof(), obviously. Do the results match up
> with what you get from R CMD Rprof? Looking at the source for
> summaryRprof, I see that it uses this construction
> 
> selft <- sapply(ls(envir = self), function(f) get(f, envir =
>     self))
>  
> which I suspect does not count function names that start with a dot...

It does not. Runnig everything through R CMD Rprof gives a much moe 
sensible output. I have no further questions.

Do I file a bug report on summaryRprof - it is certainly unintentional 
that it does not compute eg. .C calls when computing the self time?
-- 
Kasper Daniel Hansen, Research Assistant
Department of Biostatistics, University of Copenhagen