1D plots are taking longer than expected

[aashish24]

the context here is diagnostics which is taking 3 times longer than other comparable codes.

@danlipsa @doutriaux1 @danlipsa

[danlipsa]

Script from @doutriaux1
I’m running a simple script and the time does increase.

import vcs
n = 500
import time
x=vcs.init(bg=True)
 
for i in range(n):
    print i
    start = time.time()
    gm = vcs.create1d()
    x.plot([1,2,3,4,5,4,3,2,1],gm)
    x.png("crap")
    end = time.time()
    print "Time:", end-start
    x.clear()
    x.removeobject(gm)

I will fix look into this.

0
Time: 0.948871850967
1
Time: 0.861415863037
2
Time: 0.834878921509
3
Time: 0.874891042709
4
Time: 0.88400888443
5
Time: 0.920846939087
6
Time: 0.944895982742
7
Time: 0.952336072922
8
Time: 0.980937957764
9
Time: 0.998622179031
10
Time: 1.04106593132
11
Time: 1.0652089119
12
Time: 1.08572602272
13
Time: 1.10154604912
14
Time: 1.15561079979
15
Time: 1.14711499214
16

[durack1]

@danlipsa @doutriaux1 this looks eerily like CDAT/cdat#1424 #83, CDAT/cdat#2040, CDAT/cdat#2135

[danlipsa]

@durack1 Indeed. I was just looking for that issue to reference it here. 😄

[durack1]

@danlipsa once the problem that is underlying all these is rectified I think you'll be able to close 10+ open issues across the different repos.. I know that @chaosphere2112 had started some work to address these quite sometime ago, not sure if there is a branch somewhere that could be revisited?

[doutriaux1]

@danlipsa @durack1 it does not seem like we have new vcs objects created though as the following updated script shows:

import vcs

n = 10

import time
x=vcs.init(bg=True)
fastest = 100000.
elements = vcs.listelements()
cpy = vcs.elements.copy()

for i in range(n):
    print i,
    start = time.time()
    gm = vcs.create1d()
    x.plot([1,2,3,4,5,4,3,2,1],gm)
    x.png("crap")
    end = time.time()
    elapsed = end - start
    if elapsed < fastest:
        fastest = elapsed
    print "Time:", elapsed, "%.2i" % (elapsed/fastest*100.)
    x.clear()
    x.removeobject(gm)
    for e in elements:
        print "\t",e,len(vcs.elements[e])
        if len(vcs.elements[e])!=len(cpy[e]):
            print "\tMore elements in:",e,len(vcs.elements[e])

output:

0 Time: 0.924364089966 100
	1d 13
	3d_dual_scalar 1
	3d_scalar 2
	3d_vector 1
	boxfill 9
	colormap 42
	display 1
	fillarea 1
	font 16
	fontNumber 16
	isofill 9
	isoline 9
	line 17
	list 28
	marker 9
	meshfill 6
	projection 9
	scatter 1
	streamline 1
	taylordiagram 1
	template 42
	textcombined 0
	textorientation 63
	texttable 9
	vector 1
	xvsy 1
	xyvsy 1
	yxvsx 1
1 Time: 0.829059839249 100
	1d 13
	3d_dual_scalar 1
	3d_scalar 2
	3d_vector 1
	boxfill 9
	colormap 42
	display 1
	fillarea 1
	font 16
	fontNumber 16
	isofill 9
	isoline 9
	line 17
	list 28
	marker 9
	meshfill 6
	projection 9
	scatter 1
	streamline 1
	taylordiagram 1
	template 42
	textcombined 0
	textorientation 63
	texttable 9
	vector 1
	xvsy 1
	xyvsy 1
	yxvsx 1
2 Time: 0.832683086395 100
	1d 13
	3d_dual_scalar 1
	3d_scalar 2
	3d_vector 1
	boxfill 9
	colormap 42
	display 1
	fillarea 1
	font 16
	fontNumber 16
	isofill 9
	isoline 9
	line 17
	list 28
	marker 9
	meshfill 6
	projection 9
	scatter 1
	streamline 1
	taylordiagram 1
	template 42
	textcombined 0
	textorientation 63
	texttable 9
	vector 1
	xvsy 1
	xyvsy 1
	yxvsx 1
3 Time: 0.842061042786 101
	1d 13
	3d_dual_scalar 1
	3d_scalar 2
	3d_vector 1
	boxfill 9
	colormap 42
	display 1
	fillarea 1
	font 16
	fontNumber 16
	isofill 9
	isoline 9
	line 17
	list 28
	marker 9
	meshfill 6
	projection 9
	scatter 1
	streamline 1
	taylordiagram 1
	template 42
	textcombined 0
	textorientation 63
	texttable 9
	vector 1
	xvsy 1
	xyvsy 1
	yxvsx 1
4 Time: 0.879651069641 106
	1d 13
	3d_dual_scalar 1
	3d_scalar 2
	3d_vector 1
	boxfill 9
	colormap 42
	display 1
	fillarea 1
	font 16
	fontNumber 16
	isofill 9
	isoline 9
	line 17
	list 28
	marker 9
	meshfill 6
	projection 9
	scatter 1
	streamline 1
	taylordiagram 1
	template 42
	textcombined 0
	textorientation 63
	texttable 9
	vector 1
	xvsy 1
	xyvsy 1
	yxvsx 1
5 Time: 0.937988996506 113
	1d 13
	3d_dual_scalar 1
	3d_scalar 2
	3d_vector 1
	boxfill 9
	colormap 42
	display 1
	fillarea 1
	font 16
	fontNumber 16
	isofill 9
	isoline 9
	line 17
	list 28
	marker 9
	meshfill 6
	projection 9
	scatter 1
	streamline 1
	taylordiagram 1
	template 42
	textcombined 0
	textorientation 63
	texttable 9
	vector 1
	xvsy 1
	xyvsy 1
	yxvsx 1

[doutriaux1]

I suspect that somehow the objects stay in memory, @danlipsa could there be vtk objects left somewhere?

[doutriaux1]

interestingly enough, the following keeps the speed constant, ther only diff is that we create a new canvas object each and everytime! @zshaheen you might want to try this in the mean time

import vcs

n = 10

import time
fastest = 100000.
elements = vcs.listelements()
cpy = vcs.elements.copy()

for i in range(n):
    x=vcs.init(bg=True)
    print i,
    start = time.time()
    gm = vcs.create1d()
    x.plot([1,2,3,4,5,4,3,2,1],gm)
    x.png("crap")
    end = time.time()
    elapsed = end - start
    if elapsed < fastest:
        fastest = elapsed
    print "Time:", elapsed, "%.2i" % (elapsed/fastest*100.)
    x.clear()
    x.removeobject(gm)
    for e in elements:
        print "\t",e,len(vcs.elements[e])
        if len(vcs.elements[e])!=len(cpy[e]):
            print "\tMore elements in:",e,len(vcs.elements[e])

[danlipsa]

@doutriaux1 VTK objects stay in memory (as they should) if there are python objects referring to them. My concern is that we should determine the cause for the slowdown the rather then working on the first problem we find. Can you run your script a couple of hundred times to see how much slower plot gets? We start with one plot a second. How long does a plot take after 500 iterations?

[doutriaux1]

@danlipsa but doing a x=vcs.init() inside the loop removes the issue, so the x.clear() obviously leaves some references to something in there.

[doutriaux1]

@danlipsa in there: https://github.com/UV-CDAT/vcs/blob/master/vcs/VTKPlots.py#L330-L360 are we removing all vtk objects?

[danlipsa]

@doutriaux1 Not sure. I see that we delete all renderers on layers different than 0, but I am not sure if thats all. We have to be left with one renderer after that. Can you print the number of renderers in each of your iterations? (I think you have to do one of those loops as it does not seem to be a function that directly returns the number of renderers). Alternatively, there is VTK_DEBUG_LEAKS:BOOL=ON that will print VTK objects that are not removed at the end of a program.

Before we invest more time in this, how many seconds is a plot taking at iteration 500?

[doutriaux1]

@danlipsa 500 iteration:

490 Time: 15.1224999428 1366
491 Time: 15.2980108261 1381
492 Time: 14.9305939674 1348
493 Time: 14.9334559441 1348
494 Time: 15.731981039 1421
495 Time: 15.0851500034 1362
496 Time: 15.089578867 1363
497 Time: 14.9567019939 1351
498 Time: 15.3057348728 1382
499 Time: 14.8543968201 1341

[danlipsa]

@doutriaux1 That's bad! We should track this down and fix it.

[danlipsa]

@doutriaux1 Hopefully today I'll finish a different project I've been involved in since yesterday. I'll finish up the streamlines and then I can look at this probably toward the end of the week.