vcs.plot(iso) creates text object that are not removed after clear

[durack1]

Not related to #1397 (bg=1 memory leak)

[durack1]

@doutriaux1 it seems you've nailed where the slow down is happening, which is text* (and maybe some other vcs) objects accumulating throughout a loop.

The following code:

bg = False
counter = 1
for var in ['sic','sst']:
    ...
    for data in ['obs','bcs']:
    ...
        x = vcs.init()
        for count,y in enumerate(range(1870,2013)):
        ...
            for m in range(12):
                startTime                   = time.time()
                ...
                title.string                = '%i-%.2i' % (y,m+1)
                x.plot(title,bg=bg)
                x.plot(s1,t1,iso1,bg=bg)
                x.plot(diff,t2,iso2,bg=bg)
                x.plot(s2,t3,iso1,bg=bg)
                ...
                x.png(fileName)
                x.clear()
                del(vcs.elements["isofill"][iso1.name])
                del(vcs.elements["isofill"][iso2.name])
                del(vcs.elements["textcombined"][title.name])                
                del(vcs.elements["template"][t1.name])
                del(vcs.elements["template"][t2.name])
                del(vcs.elements["template"][t3.name])
                for nm in vcs.elements["texttable"].keys():
                    if not nm in basic_tt:
                        del(vcs.elements["texttable"][nm])
                for nm in vcs.elements["textorientation"].keys():
                    if not nm in basic_to:
                        del(vcs.elements["textorientation"][nm])
                for nm in vcs.elements["textcombined"].keys():
                    if not nm in basic_tc:
                        del(vcs.elements["textcombined"][nm])
                endTime                 = time.time()
                print counterStr,printStr,varName.ljust(6),BC,timeStr,memStr
                counter                 = counter+1
            gc.collect() ; # Attempt to force a memory flush
        x.close()     

Gets this output:

00001 processing: 1870-01 sic     Time: 04.401 secs; Max mem: 0.237 GB
00150 processing: 1882-06 sic     Time: 03.026 secs; Max mem: 0.244 GB
00300 processing: 1894-12 sic     Time: 03.048 secs; Max mem: 0.256 GB
00500 processing: 1911-08 sic     Time: 03.061 secs; Max mem: 0.262 GB
01000 processing: 1953-04 sic     Time: 03.079 secs; Max mem: 0.286 GB
01500 processing: 1994-12 sic     Time: 03.149 secs; Max mem: 0.306 GB
02000 processing: 1893-08 sic  bc Time: 03.640 secs; Max mem: 0.351 GB
02500 processing: 1935-04 sic  bc Time: 03.333 secs; Max mem: 0.374 GB
03000 processing: 1976-12 sic  bc Time: 03.465 secs; Max mem: 0.393 GB
03500 processing: 1875-08 tos     Time: 03.354 secs; Max mem: 0.418 GB
04000 processing: 1917-04 tos     Time: 03.679 secs; Max mem: 0.429 GB
05000 processing: 2000-08 tos     Time: 03.349 secs; Max mem: 0.496 GB
06000 processing: 1940-12 tos  bc Time: 03.656 secs; Max mem: 0.529 GB
06864 processing: 2012-12 tos  bc Time: 03.588 secs; Max mem: 0.567 GB

For comparison, the timings and resource usage (which were erroneously listed in #1397 - doesn't have much to do with the bg=True issue title) without these explicit del() were:

00001 processing: 1870-01 sic     Time: 04.093 secs; Max mem: 0.238 GB
00150 processing: 1882-06 sic     Time: 06.176 secs; Max mem: 0.255 GB
00300 processing: 1894-12 sic     Time: 10.063 secs; Max mem: 0.261 GB
00500 processing: 1911-08 sic     Time: 15.334 secs; Max mem: 0.280 GB
01000 processing: 1953-04 sic     Time: 31.086 secs; Max mem: 0.320 GB
01500 processing: 1994-12 sic     Time: 48.595 secs; Max mem: 0.352 GB
02000 processing: 1893-08 sic  bc Time: 68.674 secs; Max mem: 0.389 GB
02500 processing: 1935-04 sic  bc Time: 90.528 secs; Max mem: 0.480 GB
03000 processing: 1976-12 sic  bc Time: 111.397 secs; Max mem: 0.480 GB
03500 processing: 1875-08 tos     Time: 134.129 secs; Max mem: 0.498 GB
04000 processing: 1917-04 tos     Time: 163.216 secs; Max mem: 0.517 GB
04236 processing: 1936-12 tos     Time: 174.415 secs; Max mem: 0.525 GB

It would be great if vcs clear and vcs close did a better job of cleaning up after themselves..

[durack1]

@doutriaux1 as an aside, it also appears that the vcs ffmpeg call is also not releasing objects:

x = vcs.init()
x.ffmpeg('out.mp4',outFileList,rate=5,bitrate=2048)
x.close()

The first time it's called it seems to jump the memory usage a little:

01716 processing: 2012-12 sic     Time: 03.285 secs; Max mem: 0.319 GB
Processing:  AMIPBCS_newVsOld_sic.mp4
01717 processing: 1870-01 sic  bc Time: 03.798 secs; Max mem: 0.333 GB

Whereas subsequent calls don't appear to do the same:

03432 processing: 2012-12 sic  bc Time: 03.587 secs; Max mem: 0.418 GB
Processing:  AMIPBCS_newVsOld_sicbcs.mp4
03433 processing: 1870-01 tos     Time: 04.039 secs; Max mem: 0.418 GB
05148 processing: 2012-12 tos     Time: 03.354 secs; Max mem: 0.501 GB
Processing:  AMIPBCS_newVsOld_tos.mp4
05149 processing: 1870-01 tos  bc Time: 04.334 secs; Max mem: 0.501 GB

[durack1]

@doutriaux1 this will get you there - it's the script which reports the time and mem usage above:
https://github.com/PCMDI/amipbcs/blob/master/make_newVsOldDiffs.py

[durack1]

@doutriaux1 seems like there are some more things which aren't being purged, reopening..

Code that includes:

del(vcs.elements["isofill"][iso1.name])
del(vcs.elements["isofill"][iso2.name])
del(vcs.elements["textcombined"][title.name])                
del(vcs.elements["template"][t1.name])
del(vcs.elements["template"][t2.name])
del(vcs.elements["template"][t3.name])
for nm in vcs.elements["texttable"].keys():
  if not nm in basic_tt:
    del(vcs.elements["texttable"][nm])
for nm in vcs.elements["textorientation"].keys():
  if not nm in basic_to:
    del(vcs.elements["textorientation"][nm])
for nm in vcs.elements["textcombined"].keys():
  if not nm in basic_tc:
    del(vcs.elements["textcombined"][nm])

Yields the following timings/memory usage in a loop:

UV-CDAT version:  2.2.0
UV-CDAT prefix:  /usr/local/uvcdat/2.2.0
delFudge:  True
count                             frameTime          residentMemory
00001 processing: 1870-01 sic     Time: 03.241 secs; Max mem: 0.241 GB
...
00500 processing: 1911-08 sic     Time: 03.179 secs; Max mem: 0.274 GB
...
01000 processing: 1953-04 sic     Time: 03.169 secs; Max mem: 0.295 GB

And without:

UV-CDAT version:  2.2.0-204-geef3c60
UV-CDAT prefix:  /usr/local/uvcdat/2015-07-14-full
delFudge:  False
count                             frameTime          residentMemory
00001 processing: 1870-01 sic     Time: 03.225 secs; Max mem: 0.237 GB
...
00010 processing: 1870-10 sic     Time: 05.558 secs; Max mem: 0.238 GB
...
00020 processing: 1871-08 sic     Time: 09.972 secs; Max mem: 0.240 GB
...
00030 processing: 1872-06 sic     Time: 15.952 secs; Max mem: 0.241 GB
...
00040 processing: 1873-04 sic     Time: 23.081 secs; Max mem: 0.243 GB
...
00050 processing: 1874-02 sic     Time: 31.757 secs; Max mem: 0.246 GB
...
00060 processing: 1874-12 sic     Time: 42.138 secs; Max mem: 0.246 GB
...
00070 processing: 1875-10 sic     Time: 53.792 secs; Max mem: 0.250 GB
...
00080 processing: 1876-08 sic     Time: 68.210 secs; Max mem: 0.256 GB
...
00090 processing: 1877-06 sic     Time: 78.360 secs; Max mem: 0.263 GB
...
00100 processing: 1878-04 sic     Time: 93.911 secs; Max mem: 0.266 GB
...
00110 processing: 1879-02 sic     Time: 111.486 secs; Max mem: 0.267 GB

And just for completeness, adding back in the del statements, we get:

UV-CDAT version:  2.2.0-204-geef3c60
UV-CDAT prefix:  /usr/local/uvcdat/2015-07-14-full
delFudge:  True
count                             frameTime          residentMemory
00001 processing: 1870-01 sic     Time: 03.795 secs; Max mem: 0.241 GB
...
00020 processing: 1871-08 sic     Time: 03.140 secs; Max mem: 0.242 GB
...
00050 processing: 1874-02 sic     Time: 03.164 secs; Max mem: 0.242 GB
...
00100 processing: 1878-04 sic     Time: 03.131 secs; Max mem: 0.243 GB
...
00200 processing: 1886-08 sic     Time: 03.139 secs; Max mem: 0.245 GB
...
00500 processing: 1911-08 sic     Time: 03.179 secs; Max mem: 0.255 GB
...
01000 processing: 1953-04 sic     Time: 03.244 secs; Max mem: 0.271 GB
...
01500 processing: 1994-12 sic     Time: 03.384 secs; Max mem: 0.276 GB
...
06864 processing: 2012-12 tos  bc Time: 07.218 secs; Max mem: 0.376 GB