thr3ads.net - R help - [R] Inconsistent results between first run of Rprof and next runs of Rprof [Jan 2014]

If this information is useful, please help other people find it:
Share via:

Nathan Uyttendaele

2014-Jan-29 13:29 UTC

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

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]]

jim holtman

2014-Jan-29 21:02 UTC

head link

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

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.

R help - Jan 2014 - Inconsistent results between first run of Rprof and next runs of Rprof

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

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