Strange use of time...

*To*: mathgroup at smc.vnet.net*Subject*: [mg111240] Strange use of time...*From*: Jean-Eric <jecampagne at free.fr>*Date*: Sat, 24 Jul 2010 05:09:45 -0400 (EDT)

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}