Re: Strange use of time...

*To*: mathgroup at smc.vnet.net*Subject*: [mg111241] Re: Strange use of time...*From*: David Bailey <dave at removedbailey.co.uk>*Date*: Sun, 25 Jul 2010 01:56:38 -0400 (EDT)*References*: <i2eak9$qam$1@smc.vnet.net>

On 24/07/10 10:09, Jean-Eric wrote: > Hello, > See below a short test of the time used by a function > brpCrossCorrCh1AndCh2[]; > Looking at the time spent it turns out that > 1) the total time spend by the Do-Loop is governed by few calls to the > above brpCrossCorrCh1AndCh2; > 2) the distribution of time spend is strange at first look: mostly ~< > 10^-16 sec or few ~0.015 sec! > 3) the proportion of large time spent (~0.015sec) depends on the > number of complex data generated and then treat by > brpCrossCorrCh1AndCh2 > > I have tried to tackle from where the large time spent come from. > Working on Latitude E6400 dual processor running Windows XP, I have > looked at memory, cpu... I have turn off FireFox... > But nothing change. > > So I come with the below short nb file that you can run in your > computer and let me know if you experience the some strange behavior > mentionned above. > > Sincerely > Jean-Eric > > > > In[1]:= $HistoryLength =0; > In[2]:= memStart =MemoryInUse[]; > In[3]:= Clear[profiletime]; > Attributes[profiletime]={HoldAll}; > profiletime[expr_,tag_]:=Module[{results=Timing[expr]},Sow[First@results,tag]; > Last@results] > In[6]:= data = RandomComplex[10+5 I,{2,10000}]; > cplxAmpCh1=data[[1]]; > cplxAmpCh2= data[[2]]; > In[9]:= Clear[brpCrossCorrCh1AndCh2]; > brpCrossCorrCh1AndCh2[f_Integer:1,l_Integer:-1]:=Module[{corr}, > corr = Total[N[cplxAmpCh1[[f;;l]]*Conjugate[cplxAmpCh2[[f;;l]]]]]; > corr /= Length[ cplxAmpCh1[[f;;l]]]; > (* result *) > {Re[corr],Im[corr]} > ];(* end of module *) > In[11]:= tStart = Sow[TimeUsed[]]; > dataTime=Last@Reap[ > Do[profiletime[Module[{}, > (*brpAutoCorrCh1AndCh2[];*) > brpCrossCorrCh1AndCh2[]; > ];,"crossCorr"],{i,1000}] > ]; > In[13]:= Print["Time used ",Sow[TimeUsed[]]-tStart] > Print["Memory used ",MemoryInUse[]-memStart] > During evaluation of In[13]:= Time used 0.437 > During evaluation of In[13]:= Memory used 603728 > In[15]:= ListPlot[dataTime,PlotRange->Full] > In[16]:= Max[dataTime] > Out[16]= 0.016 > In[17]:= BinCounts[dataTime[[1]],{0,0.02,0.01}] > Out[17]= {972,28} > To get meaningful timing results you absolutely have to time computations that take (say) 10 seconds or longer. The reason for this, is that there are always other things going on inside your computer, and these cannot be totally accounted for, even by Timing, which tries to time a computation without including time spent on other processes. David Bailey http://www.dbaileyconsultancy.co.uk