[R] Inconsistent results between first run of Rprof and next runs of Rprof

[jim holtman]

You should at least post the script so that we see what line 33 is.
For example, was it an input statement so that on the second time you
ran the data was cached in memory?  Did you remove all the objects and
do a gc() to clean up memory before trying again (maybe there was some
data hanging around that helped out).  It is not unknown to get
different results if you are having to access, especially, external
data.

Jim Holtman
Data Munger Guru

What is the problem that you are trying to solve?
Tell me what you want to do, not how you want to do it.


On Wed, Jan 29, 2014 at 8:29 AM, Nathan Uyttendaele <na.uytten at gmail.com> wrote:
> Hello,
>
> when I run this code in a brand new R session
>
> --------------------------------------------------
> ### loading of libraries and other functions
>
> Rprof("profiling.out")
> start.time=proc.time()[3]
> for(i in 1:50) {
> main.function()
> }
> end.time=proc.time()[3]
> Rprof()
> ---------------------------------------------------
>
> I get as result of the profiling
>
> estimateNACstructureof.R#33    56.6900000
>
> estimateNACstructureof.R#93     5.2200000
>
> estimateNACstructureof.R#87     4.9700000
>
> estimateNACstructureof.R#78     1.9400000
>
> oldFriedman.R#39                1.2600000
>
> estimateNACstructureof.R#81     1.2100000
>
> estimateNACstructureof.R#88     1.2000000
>
> estimateNACstructureof.R#657    0.9600000
>
> todecompose.R#34                0.6900000
>
> estimateNACstructureof.R#658    0.6600000
>
> estimateNACstructureof.R#264    0.6500000
>
> estimateNACstructureof.R#923    0.5900000
>
> aresameNACstructures.R#4        0.5600000
>
> estimateNACstructureof.R#1059   0.4800000
>
> estimateNACstructureof.R#1064   0.4700000
>
> estimateNACstructureof.R#22     0.4600000
>
> estimateNACstructureof.R#659    0.4500000
>
> nicenodenames.R#22              0.4400000
>
> estimateNACstructureof.R#1029   0.4200000
>
> todecompose.R#119               0.4200000
>
> estimateNACstructureof.R#1061   0.4000000
>
> estimateNACstructureof.R#654    0.3800000
>
> todecompose.R#12                0.3800000
>
> estimateNACstructureof.R#85     0.3700000
>
> estimateNACstructureof.R#89     0.3700000
>
> todecompose.R#19                0.3500000
>
> todecompose.R#160               0.3500000
>
> estimateNACstructureof.R#1060   0.3300000
>
> estimateNACstructureof.R#83     0.3100000
>
> todecompose.R#144               0.3100000
>
> sampling.time 207.1400000
>
> total.elapsed.time  235.9440000
>
> total.elapsed.time/samping.time*100    87.79202
>
>
> Except for the 3 last rows, what we have is the self.pct value in
> decreasing order, by line.
>
>
> What I do not understand is that if am to run the same code all over again,
> I now get
>
>
> estimateNACstructureof.R#852       4.34000
>
> estimateNACstructureof.R#923       3.94000
>
> estimateNACstructureof.R#87        3.38000
>
> estimateNACstructureof.R#93        3.31000
>
> estimateNACstructureof.R#859       2.70000
>
> estimateNACstructureof.R#1029      2.27000
>
> estimateNACstructureof.R#657       1.65000
>
> estimateNACstructureof.R#933       1.51000
>
> estimateNACstructureof.R#78        1.49000
>
> estimateNACstructureof.R#721       1.49000
>
> todecompose.R#34                   1.49000
>
> estimateNACstructureof.R#658       1.39000
>
> estimateNACstructureof.R#1064      1.26000
>
> estimateNACstructureof.R#1059      1.25000
>
> estimateNACstructureof.R#659       1.21000
>
> estimateNACstructureof.R#1061      1.20000
>
> aresameNACstructures.R#4           1.17000
>
> estimateNACstructureof.R#1060      1.09000
>
> todecompose.R#12                   1.00000
>
> todecompose.R#145                  0.98000
>
> estimateNACstructureof.R#723       0.97000
>
> getNACadjacencyof.R#10             0.97000
>
> estimateNACstructureof.R#709       0.96000
>
> oldFriedman.R#39                   0.90000
>
> estimateNACstructureof.R#81        0.89000
>
> estimateNACstructureof.R#88        0.88000
>
> estimateNACstructureof.R#708       0.88000
>
> todecompose.R#119                  0.86000
>
> todecompose.R#160                  0.84000
>
> estimateNACstructureof.R#715       0.83000
>
> sampling.time                    198.38000
>
> total.elapsed.time                   203.56800
>
> total.elapsed.time /samping.time*100  97.45147
>
>
>
> And the line 33 of estimateNACstructureof, which previously was observed
> 56.69% of the sampling time is now... gone ! If I profile he code in the
> same R session again and again, line 33 of estimateNACstructureof seems
> never to appear again.
>
>
> In fact the line 33 of estimateNACstructureof appears only when Rprof is
> run for the first time in the R session.
>
>
> Note: this is maybe relevant, the line 33 of estimateNACstructureof refers
> to C function.
>
>
> Any thoughts of what I get this peculiar result?
>
>         [[alternative HTML version deleted]]
>
> ______________________________________________
> R-help at r-project.org mailing list
> https://stat.ethz.ch/mailman/listinfo/r-help
> PLEASE do read the posting guide http://www.R-project.org/posting-guide.html
> and provide commented, minimal, self-contained, reproducible code.