performance crashes with multiple calls of createisofill

[painter1]

I am repeatedly (17 times) calling a function which generates a set of four plots with VCS. They should all take about the same time. With normal use of VCS, they don't. Each is slower than the one before, and you get an overall slowdown of well over an order of magnitude - enough to make VCS almost unusable.

I narrowed the problem down to vcs.elements['isofill']. Each time my function is called another 10 or so names get added to this list. The running time of canvas.plot is superlinear in the length of vcs.elements['isofill'].

As a workaround, I saved a copy of an early form of vcs.elements, and restored it (other than vcs.elements['display']) frequently. This completely eliminated the performance problem, and my test problem's running time went from 3 1/2 hours to 16 minutes.

It seems to me that something in VCS does something very expensive with everything in vcs.elements['isofill']. There may be design issues - why does everything have to be saved forever? - but that is beyond my competence to judge.

[chaosphere2112]

Everything gets saved forever because people can plot isofills just using the name of the graphics method:

import vcs
import cdms2
f = cdms2.open(vcs.sample_data + '/clt.nc')
s = f('clt')
x = vcs.init()
iso = x.createisofill()
x.isofill(s, iso.name) # also x.plot(s, "isofill", iso.name)

If people stash the name of a graphics method, they'll still be able to use it later unless they actively prevent themselves from doing so.

That said, I just ran this:

import cProfile
import vcs
x = vcs.init()
import cdms2
f = cdms2.open(vcs.sample_data + "/clt.nc")
s = f('clt')
def plot():
    x.clear()
    i = x.createisofill()
    x.plot(s, i)
def test_plot():
    for i in range(1000):
        plot()
cProfile.run('test_plot()')

And got these results (trimmed everything that used less than a quarter of a second):

ncalls	tottime	percall	cumtime	percall filename:lineno(function)
1999	41.783	0.021	41.783	0.021 {method 'Render' of 'vtkRenderingCorePython.vtkRenderWindow' objects}
7000	21.667	0.003	21.879	0.003 Canvas.py:2475(__new_elts)
46592000	12.979	0	12.979	0.000 collections.py:90(iter)
6002	9.859	0.002	9.859	0.002 {method 'Update' of 'vtkCommonExecutionModelPython.vtkAlgorithm' objects}
1637000	8.234	0	8.234	0.000 {sorted}
918000	7.466	0	58.674	0.000 copy.py:306(_reconstruct)
15984	6.861	0	6.861	0.000 {method 'RemoveAllViewProps' of 'vtkRenderingCorePython.vtkViewport' objects}
918000	5.703	0	6.596	0.000 {method 'reduce_ex' of 'object' objects}
14000	5.572	0	7.601	0.001 vcs2vtk.py:1125(genTextActor)
5190000	5.165	0	16.778	0.000 VCS_validation_functions.py:177(checkNumber)
9195000	5.162	0	10.439	0.000 VCS_validation_functions.py:409(checkName)
10974006	5.013	0	5.922	0.000 {hasattr}
1664000	4.92	0	17.9	0.000 collections.py:117(keys)
5270000	4.478	0	5.82	0.000 VCS_validation_functions.py:165(isNumber)
11857018	3.801	0	54.378	0.000 {setattr}
20686003	3.647	0	3.662	0.000 {isinstance}
1166000	3.497	0	3.497	0.000 {method 'write' of 'file' objects}
610000	3.247	0	3.247	0.000 {posix.stat}
1636000	3.018	0	29.885	0.000 utils.py:245(listelements)
7080022/7044022	2.863	0	2.944	0.000 {getattr}
18000	2.744	0	74.829	0.004 template.py:224(init)
999001	2.358	0	68.589	0.000 copy.py:66(copy)
21000/1000	2.34	0	244.172	0.244 Canvas.py:2482(__plot)
1000	2.335	0.002	3.02	0.003 vcs2vtk.py:213(setInfToValid)
587000	2.091	0	9.709	0.000 VCS_validation_functions.py:209(checkListOfNumbers)
1000	1.824	0.002	255.88	0.256 :1(plot)
2898979	1.788	0	1.788	0.000 {method 'keys' of 'dict' objects}
300000	1.703	0	3.183	0.000 core.py:2763(_update_from)
6000	1.611	0	6.754	0.001 vcs2vtk.py:1640(prepLine)
200004	1.572	0	1.814	0.000 cdmsobj.py:457(_listatts)
220000	1.56	0	5.537	0.000 core.py:2788(array_finalize)
18000	1.502	0	7.767	0.000 traceback.py:281(extract_stack)
18000	1.448	0	5.603	0.000 traceback.py:16(print_list)
4000	1.38	0	47.663	0.012 template.py:1026(drawTicks)
1106000	1.259	0	5.754	0.000 VCS_validation_functions.py:201(checkInt)
612000	1.252	0	15.986	0.000 VCS_validation_functions.py:945(checkTextOrientation)
918000	1.236	0	1.82	0.000 template.py:48(_setgen)
1313050	1.102	0	1.178	0.000 {numpy.core.multiarray.array}
612000	1.021	0	10.649	0.000 VCS_validation_functions.py:923(checkTextTable)
592000	1.012	0	4.06	0.000 linecache.py:47(checkcache)
369024	0.86	0	1.24	0.000 {method 'reduce' of 'numpy.ufunc' objects}
87000	0.851	0	1.278	0.000 VCS_validation_functions.py:1294(checkInStringsListInt)
45000	0.849	0	1.151	0.000 vcs2vtk.py:1071(prepTextProperty)
243000	0.847	0	0.847	0.000 VCS_validation_functions.py:1578(getProjType)
19000/1000	0.841	0	237.315	0.237 VTKPlots.py:565(plot)
368004	0.83	0	1.723	0.000 numeric.py:2428(seterr)
592000	0.744	0	5.084	0.000 compilerop.py:137(check_linecache_ipython)
57000	0.704	0	2.414	0.000 numeric.py:2156(allclose)
99000	0.697	0	3.406	0.000 manageElements.py:32(check_name_source)
384000	0.685	0	1.014	0.000 core.py:621(getdata)
67000	0.684	0	2.421	0.000 tvariable.py:85(_update_from)
320000	0.67	0	5.647	0.000 VCS_validation_functions.py:141(checkLine)
74000	0.663	0	4.096	0.000 core.py:2638(new)
2002000	0.659	0	0.659	0.000 {method 'update' of 'dict' objects}
368004	0.647	0	0.681	0.000 numeric.py:2524(geterr)
1076000	0.595	0	0.9	0.000 template.py:44(_getgen)
29000	0.587	0	5.431	0.000 texttable.py:370(init)
5481436/5244436	0.586	0	0.678	0.000 {len}
4762000	0.583	0	0.583	0.000 line.py:153(_getname)
2000	0.575	0	0.575	0.000 {method 'GetXRange' of 'vtkRenderingCorePython.vtkProp3D' objects}
1166000	0.573	0	4.071	0.000 traceback.py:12(_print)
33000	0.559	0	15.861	0.000 tvariable.py:142(init)
70000	0.542	0	0.58	0.000 numerictypes.py:949(_can_coerce_all)
29000	0.539	0	14.847	0.001 axis.py:1656(init)
592000	0.534	0	0.882	0.000 linecache.py:13(getline)
71000	0.532	0	2.003	0.000 core.py:925(call)
918000	0.523	0	4.924	0.000 VCS_validation_functions.py:1716(_setpriority)
187000	0.496	0	3.56	0.000 VCS_validation_functions.py:732(checkColor)
1000	0.489	0	1.374	0.001 vcs2vtk.py:1226(prepFillarea)
3680000	0.485	0	0.485	0.000 texttable.py:170(_getname)
35000	0.484	0	2.962	0.000 core.py:6650(where)
21000	0.398	0	5.554	0.000 Canvas.py:99(_determine_arg_list)
999	0.394	0	0.394	0.000 {method 'IsDrawable' of 'vtkRenderingOpenGLPython.vtkCocoaRenderWindow' objects}
449001	0.39	0	0.39	0.000 core.py:3359(_get_data)
612000	0.381	0	16.367	0.000 VCS_validation_functions.py:1812(_settexorientation)
612000	0.375	0	11.025	0.000 VCS_validation_functions.py:1803(_settextable)
918000	0.369	0	0.537	0.000 copy_reg.py:92(newobj)
35000	0.362	0	1.246	0.000 VCS_validation_functions.py:90(checkContinents)
2432005	0.359	0	0.359	0.000 {method 'get' of 'dict' objects}
1000	0.343	0	182.231	0.182 isofillpipeline.py:21(_plotInternal)
1000	0.342	0	137.567	0.138 template.py:1429(plot)
33000	0.339	0	0.557	0.000 avariable.py:120(init)
532437	0.338	0	0.338	0.000 {range}
558000	0.336	0	2.15	0.000 VCS_validation_functions.py:1794(_setY)
6626000	0.336	0	0.336	0.000 {math.isinf}
1000	0.327	0	8.97	0.009 VTKPlots.py:323(clear)
2539281	0.324	0	0.324	0.000 {method 'append' of 'list' objects}
10000	0.317	0	0.317	0.000 {method 'SetInputData' of 'vtkRenderingCorePython.vtkPolyDataMapper' objects}
1000	0.313	0	6.415	0.006 utils.py:982(mklabels)
134000	0.308	0	0.517	0.000 template.py:64(epsilon_lte)
558000	0.303	0	1.956	0.000 VCS_validation_functions.py:1767(_setX)
29000	0.303	0	2.166	0.000 textorientation.py:193(init)
147000	0.299	0	0.534	0.000 core.py:389(_check_fill_value)
1277302	0.297	0	0.297	0.000 {method 'strip' of 'str' objects}
22000	0.294	0	1.698	0.000 core.py:6131(power)
3313000	0.293	0	0.293	0.000 {method 'GetPoint' of 'vtkCommonCorePython.vtkPoints' objects}
40000	0.283	0	0.351	0.000 queries.py:51(isgraphicsmethod)
10000	0.28	0	0.735	0.000 VTKPlots.py:1319(fitToViewport)
32000	0.28	0	4.223	0.000 tvariable.py:243(new)
99000	0.252	0	0.272	0.000 random.py:175(randrange)

In [15]: len(vcs.elements["isofill"])
Out[15]: 1010

The offending function is __new_elts on vcs.Canvas; it diffs two renditions of vcs.elements against each other to determine what all was created in the plotting of a graphics method, in order to clean those up when the canvas is cleared later. That's a pretty expensive operation, and apparently we're doing it at least 7 times per plot of isofill. Should strongly consider an alternative method for cleaning up misc. VCS objects instead of this technique; maybe something like a canvas-wide flag for "we're plotting right now" that all elements get added to instead of vcs.elements? That way the internally created ones are not exposed to the outside. @doutriaux1 @danlipsa

[danlipsa]

@painter1 @chaosphere2112 Why would one create a new graphics method for each plot? In this case one would expect things to accumulate. Is this what is happening in Jeff's plot? Jeff, can you post the relevant function you are calling?

[painter1]

I ran my code three times for different timing purposes.

The first is to demonstrate the problem with only two plots. This is logically the minimum number of plots to show a slowdown as you make more plots. The time for all calls of canvas.plot():
first plot: 6.851 seconds
second plot: 17.480 seconds.
These are complicated plots. Building one of them requires three calls of canvas.plot(). It has multiple graphics components and even more text fields. Nevertheless, I don't think there should be a noticeable slowdown with less than a dozen plots, let alone two.

The second run was the same, except with a call of canvas.clean_auto_generated_objects() before making a plot:
first plot: 6.441 seconds
second plot: 6.344 seconds
So calling this method will work around the problem perfectly. __new_elts isn't cheap at 5.6% of run time, but it's far from dominant.

The third run was of my whole suite of 17 plot sets, 4 plots per set. Now again, I'm not calling clean_auto_generated_objects() or forcibly resetting vcs.elements.
first plot: 13.25 seconds
second plot: 33.92 seconds
seventeenth plot: 1786.06 seconds
The slowdown ratio between plot sets 1 & 17 is 135. Over all plots, over 77% of the time was spent in __new_elts(), which was called 816 times.

[painter1]

I gave up on calling clean_auto_generated_objects(). It doesn't work. The problem occurs if you use EzTemplate.Multi (in vcsaddons). The templates this object makes contain things (like text orientation) with names beginning with '__', so they get cleaned as the should be. But the templates themselves don't have such names, so they don't get cleaned. If you change the names so that they get cleaned out, then you run into the problem that the Multi object keeps its own list. You have to keep track of Multi objects and call their clean methods too. I fear that if I were to make all these changes, I would soon discover another way in which clean_auto_generated_objects() doesn't work.

It's simpler, and in practice much more reliable, to save and restore vcs.elements.