The plotting of 120 plots and clearing is taking too long

[williams13]

When plotting, 120 pictures and clearing the canvas to plot another image takes longer and longer as time goes on. The memory is growing so it much be calling VTK pipeline commands and copying data instead of pointing to the data.

import vcs, cdms2
cdmsfile = cdms2.open( 'clt.nc' )
data = cdmsfile('clt')
x=vcs.init()
ts=time.time()
for i in range (120):
   x.plot(data[i])   # or run it in background mode x.plot(data[I], bg=1)  --> the time to run is the same
   x.clear()

Could there be something in VTK that causes the plots to generate slowly?

[allisonvacanti]

To update this with an off-list conversation:

I ran a profiler while generating the 120th (slowest) frame. The results show that a bulk of the time is spent in the function template.P.__init__, in particular, copy.copy. I did a little poking around and measured the time it took to execute the block of copy.copy calls (template.py lines 402-478):

First Frame Benchmark	First Frame	120th Frame
Number of template.P.__init__ calls	36	37
Time per copy.copy call	~0.0023s	~0.072s (~3100% increase)
Total time to create frame	0.73s	3.4s
Total time spent copying in P.__init__	0.083s (11%)	2.6s (72%)
Time spent rendering, etc	0.647s (88%)	0.80 (24%)

These weren't the most precise benchmarking methods and the calculations are rough, but this definitely seems to be the issue: Non-copy operations went from .65 -> .80 seconds, while this copy operation jumped from 0.083 --> 2.6 seconds.

Now, why does the copy time balloon like this? Should these template attributes be growing with each frame?

If it helps, here's the stack where the copy is happening:

 /ssd/src/uvcdat-build/install/lib/python2.7/site-packages/vcs/Canvas.py(2574)plot()
-> a = self.__plot( arglist, keyargs )
  /ssd/src/uvcdat-build/install/lib/python2.7/site-packages/vcs/Canvas.py(2731)__plot()
-> copy_tmpl=self.createtemplate(source=arglist[2])
  /ssd/src/uvcdat-build/install/lib/python2.7/site-packages/vcs/Canvas.py(1296)createtemplate()
-> return vcs.createtemplate(name,source)
  /ssd/src/uvcdat-build/install/lib/python2.7/site-packages/vcs/manageElements.py(69)createtemplate()
-> return template.P(name, source)
> /ssd/src/uvcdat-build/install/lib/python2.7/site-packages/vcs/template.py(485)__init__()
-> vcs.elements["template"][Pic_name]=self

[aashish24]

@doutriaux1 please follow with @dlonie on this. This is a critical issue.

[doutriaux1]

@dlonie which profiler did you use and how did you run it. It would be useful to know.

[allisonvacanti]

cProfile (https://docs.python.org/2/library/profile.html)

[doutriaux1]

hum... it's not JUST vcs because the following also sees memory growing a bit:

import cdms2, os, sys
cdmsfile = cdms2.open( os.path.join(sys.prefix,"sample_data",'clt.nc' ))
data = cdmsfile('clt')
i=0
while 1:
  d=data[i]
  i+=1
  if i==120:
    i=0

[williams13]

Then this must be in CDMS. what if you use square brackets?

data = cdmsfile['clt']

[doutriaux1]

I think it's both...
So far, I got the speed to go down from 1.26s per frame to .48s since 2.0.0
Still about .3s seem to be spend drawing the template and colorbar. I'm sure we can improve that.

[doutriaux1]

just tested it it seems to be ok now, closing:
time between frames bellow:

0.244277000427
0.240011930466
0.248420953751
0.244468927383
0.245052814484
0.243762969971
0.240240097046
0.244555950165
0.24751996994
0.237789869308
0.238754034042
0.238749980927
0.247494935989
0.237429857254
0.239832878113
0.243031024933
0.241904020309
0.246157884598
0.240160942078
0.242171049118
0.247576951981
0.245303869247
0.237435817719
0.244822978973
0.244470834732
0.24508690834
0.240806818008
0.239790916443
0.24764418602
0.249076128006