[Rd] Interpretting R profiling output (was More efficient code?)

[Duncan Murdoch]

Gavin Simpson wrote:
> On Wed, 2005-07-06 at 19:54 +0100, Gavin Simpson wrote:
> 
>>Dear List,
>>
> 
> 
> I fixed up the code in coinertiaI to only return the bits I needed from
> La.svd() within the permutations - thus producing a 10% speed up. I am
> still a little unclear about the results from Rprof() (below).
> 
> Do the timings under self time for .Call and .Fortran include the time
> spent actually running the called compiled code or are they the overhead
> of setting up the calls to the compiled code?

They include both.  The profiler only sees R calls, it doesn't know what 
goes on within functions.  .Call() is an R call which internally calls 
some C function, but the profiler just sees the call to .Call.

Duncan Murdoch
> 
> Many thanks,
> 
> Gav
> 
> 
>>summaryRprof(filename = "Rprof.out")
>>$by.self
>>                     self.time self.pct total.time total.pct
>>".Call"                  50.40     59.6      50.40      59.6
>>"%*%"                    10.50     12.4      10.50      12.4
>>".Fortran"                2.78      3.3       2.78       3.3
>>"La.svd"                  2.52      3.0      57.98      68.6
>>"^"                       2.48      2.9       2.48       2.9
>>"t.default"               2.30      2.7       2.30       2.7
>>"matrix"                  1.92      2.3       1.98       2.3
>>"as.double"               1.78      2.1       2.70       3.2
>>"list"                    0.88      1.0       0.88       1.0
>>"as.double.default"       0.86      1.0       0.86       1.0
>>"rep.default"             0.74      0.9       0.86       1.0
>>"sum"                     0.72      0.9       2.58       3.1
>>"!"                       0.50      0.6       0.50       0.6
>>"diag"                    0.44      0.5       1.46       1.7
>>"qr.coef"                 0.42      0.5       6.26       7.4
>>"permtest"                0.38      0.4      83.60      98.9
>>"is.finite"               0.38      0.4       0.38       0.4
>>"storage.mode<-"          0.36      0.4       3.26       3.9
>>"as.integer"              0.34      0.4       0.40       0.5
>>"t"                       0.32      0.4       2.62       3.1
>>"$"                       0.32      0.4       0.32       0.4
>>"paste"                   0.28      0.3       0.54       0.6
>>"teststat"                0.24      0.3      83.10      98.3
>>"residualMatrix"          0.22      0.3      10.32      12.2
>>"qr"                      0.20      0.2       1.24       1.5
>>...
>>
>>$by.total
>>                     total.time total.pct self.time self.pct
>>"predcoca.perm"           84.50     100.0      0.00      0.0
>>"permtest"                83.60      98.9      0.38      0.4
>>"teststat"                83.10      98.3      0.24      0.3
>>"coinertiaI"              73.24      86.7      0.18      0.2
>>"La.svd"                  57.98      68.6      2.52      3.0
>>".Call"                   50.40      59.6     50.40     59.6
>>"%*%"                     10.50      12.4     10.50     12.4
>>"residualMatrix"          10.32      12.2      0.22      0.3
>>"qr.coef"                  6.26       7.4      0.42      0.5
>>"storage.mode<-"           3.26       3.9      0.36      0.4
>>".Fortran"                 2.78       3.3      2.78      3.3
>>"as.double"                2.70       3.2      1.78      2.1
>>"t"                        2.62       3.1      0.32      0.4
>>"eval"                     2.62       3.1      0.14      0.2
>>"sum"                      2.58       3.1      0.72      0.9
>>...
>>