Serious speed regressions in sage-4.7.2.alpha3

[Jeroen Demeyer]

I have prepared some small Sage scripts at:
http://boxen.math.washington.edu/home/jdemeyer/J0_46_disc.sage
http://boxen.math.washington.edu/home/jdemeyer/crystal.sage
http://boxen.math.washington.edu/home/jdemeyer/cyclomat.sage
http://boxen.math.washington.edu/home/jdemeyer/ellbsd.sage
http://boxen.math.washington.edu/home/jdemeyer/elltest1.sage
http://boxen.math.washington.edu/home/jdemeyer/elltest2.sage

Testing the timing of these scripts with
$ time ./sage elltest1.sage

yields on sage.math.washington.edu:

J0_46_disc.sage:
* sage-4.7.2.alpha2: 8s
* sage-4.7.2.alpha3: 11s

crystal.sage:
* sage-4.7.2.alpha0: 4s
* sage-4.7.2.alpha2: 9s

cyclomat.sage:
* sage-4.7.2.alpha2: 6s
* sage-4.7.2.alpha3: 9s

ellbsd.sage:
* sage-4.7.2.alpha2: 6s
* sage-4.7.2.alpha3: 14s

elltest1.sage:
* sage-4.7.2.alpha2: 23s
* sage-4.7.2.alpha3: 35s

elltest2.sage:
* sage-4.7.2.alpha2: 17s
* sage-4.7.2.alpha3: 62s

In all cases, a significant regression.

[Simon King]

Hi Jeroen,

On 5 Okt., 15:27, Jeroen Demeyer <jdeme...@cage.ugent.be> wrote:
> In all cases, a significant regression.

That's a very bad news for me, because it seems that #9138 is to blame
for it (or at least for the regression in your first example), and is
at the same time fundamental for my current project. I thought that I
managed to avoid a regression (see #9138 for a discussion), but
apparently I missed something.

I tried to find out what function calls seem to cause the regression,
but apparently %prun has problems with my terminal - I only see part
of the output. Can you point the finger on a specific method that
shows the worst regression?

Best regards,
Simon

[Simon King]

PS:

It seems that a serious part of the regression occurs in the `gens()`
method of the endomorphism ring.

sage: E = J0(46).endomorphism_ring()
sage: %time g = E.gens()
CPU times: user 7.94 s, sys: 0.15 s, total: 8.08 s
Wall time: 8.11 s

in 4.7.2.alpha3, but

sage: E = J0(46).endomorphism_ring()
sage: %time g = E.gens()
CPU times: user 5.50 s, sys: 0.31 s, total: 5.81 s
Wall time: 5.82 s

in alpha2.

[Jeroen Demeyer]

On 2011-10-05 15:27, Jeroen Demeyer wrote:
> crystal.sage:
> * sage-4.7.2.alpha0: 4s
> * sage-4.7.2.alpha2: 9s

This one is probably not a true regression, in #11183 a test was added
to the testsuite making it take more time.

[daveloeffler]

Hi Simon,

I posted some profiler output on the sage-nt list earlier today. The
methods "category.join" and "category.hom_category" were getting
called a ludicrous number of times (several thousand in the course of
a single elliptic curve calculation), which was not the case in
pre-4.7.2.alpha3. Are these being called every time any element of any
category is constructed?

David

[Simon King]

Hi Dave,

On 5 Okt., 20:55, daveloeffler <dave.loeff...@gmail.com> wrote:
> I posted some profiler output on the sage-nt list earlier today. The
> methods "category.join" and "category.hom_category" were getting
> called a ludicrous number of times (several thousand in the course of
> a single elliptic curve calculation), which was not the case in
> pre-4.7.2.alpha3. Are these being called every time any element of any
> category is constructed?

The hom_category method of a category does in fact call the join
method. And what is surprising for me: hom_category is not a cached
method. It should be. After all, categories ARE unique, and thus it
wouldn't hurt at all to cache the output of hom_category, rather than
computing the join over and over again.

I'll try if it helps to make it a cached method.

Best regards,
Simon

[Simon King]

Hi Jeroen!

Did you open a ticket for the regression, by the way?

Using cached_method/cached_function for both hom_category and join, I
get in sage-4.6.2.alpha3:

ncalls tottime percall cumtime percall
filename:lineno(function)
204 0.973 0.005 1.413 0.007 {method 'left_kernel' of
'sage.matrix.matrix2.Matrix' objects}
622 0.344 0.001 1.036 0.002 {method 'echelon_form'
of 'sage.matrix.matrix_rational_dense.Matrix_rational_dense' objects}
46 0.245 0.005 0.928 0.020 {method 'solve_left' of
'sage.matrix.matrix2.Matrix' objects}
25005 0.229 0.000 0.229 0.000 {method 'list' of
'sage.modules.free_module_element.FreeModuleElement' objects}
3210 0.229 0.000 1.284 0.000 matrix_space.py:
225(__init__)
2924 0.228 0.000 0.228 0.000 dynamic_class.py:
258(dynamic_class_internal)
53699/44827 0.216 0.000 0.499 0.000 classcall_metaclass.py:
131(__call__)
4330 0.194 0.000 0.283 0.000 matrix_space.py:
1158(matrix)
66 0.193 0.003 0.195 0.003 {method
'_rational_kernel_iml' of
'sage.matrix.matrix_integer_dense.Matrix_integer_dense' objects}
11840/5794 0.181 0.000 0.781 0.000 lazy_attribute.py:
506(__get__)
97 0.154 0.002 0.347 0.004 {method 'solve_right' of
'sage.matrix.matrix2.Matrix' objects}

Compared with sage-4.7.2.alpha2:

ncalls tottime percall cumtime percall
filename:lineno(function)
201 0.958 0.005 1.203 0.006 {method 'left_kernel' of
'sage.matrix.matrix2.Matrix' objects}
622 0.341 0.001 0.559 0.001 {method 'echelon_form'
of 'sage.matrix.matrix_rational_dense.Matrix_rational_dense' objects}
24980 0.295 0.000 0.295 0.000 {method 'list' of
'sage.modules.free_module_element.FreeModuleElement' objects}
46 0.241 0.005 0.438 0.010 {method 'solve_left' of
'sage.matrix.matrix2.Matrix' objects}
4398 0.191 0.000 0.303 0.000 matrix_space.py:
1128(matrix)
88 0.177 0.002 0.287 0.003 {method 'solve_right' of
'sage.matrix.matrix2.Matrix' objects}
60 0.172 0.003 0.173 0.003 {method
'_rational_kernel_iml' of
'sage.matrix.matrix_integer_dense.Matrix_integer_dense' objects}
1385 0.137 0.000 1.929 0.001 free_module.py:
4812(__init__)
16321/16297 0.135 0.000 0.204 0.000 free_module.py:
772(__call__)
10784/9778 0.119 0.000 0.831 0.000 matrix_space.py:
316(__call__)
3426 0.118 0.000 0.444 0.000 matrix_space.py:
225(__init__)
158551 0.112 0.000 0.112 0.000 {isinstance}
40967 0.102 0.000 0.124 0.000 {hasattr}

Thus, the difference between alpha2 and alpha3 can be reduced (thus,
there is hope that #9138 can be preserved...).

The main difference that I still see is the creation of matrix spaces.
matrix_space.py *is* touched in #9138, but so far it is not clear to
me how these changes could possibly be responsible for the slow down.

Best regards,
Simon

[Simon King]

Sorry, I forgot to provide the commands that I used for the data in my
previous post:

sage: E = J0(46).endomorphism_ring()
sage: %prun g = E.gens()

[Simon King]

Hi!

Here is an example that focuses on matrix space creation:

sage: def test(n):
....: for i in range(1,n):
....: M = MatrixSpace(QQ,i)
....:

With sage-4.7.2.alpha3:

sage: %time test(1000)
CPU times: user 0.47 s, sys: 0.00 s, total: 0.48 s
Wall time: 0.48 s
sage: %timeit test(1000)
25 loops, best of 3: 6.27 ms per loop

With sage-4.7.2.alpha2:

sage: %time test(1000)
CPU times: user 0.14 s, sys: 0.00 s, total: 0.14 s
Wall time: 0.14 s
sage: %timeit test(1000)
5 loops, best of 3: 60.7 ms per loop

So, rather amazingly, the creation of new matrix spaces became a lot
slower in alpha3, whereas returning a known matrix space became much
faster.

Cheers,
Simon

[Jeroen Demeyer]

On 2011-10-05 22:01, Simon King wrote:
> Hi Jeroen!
>
> Did you open a ticket for the regression, by the way?

No, but you should do it.

[Simon King]

It is #11900

[Simon King]

Hi!

I think I would be able to fix the regression, but I'd like to ask
whether you would object to my approach.

The ticket is #11900.

1. Provide a custom .list() method for both rational and integral
dense vectors. Currently, they use a generic implementation.
I guess you will agree that a custom implementation of a frequently
used method makes sense.

2. Use caching for sage.categories.Category.hom_category and
sage.categories.Category.join. The result is cached anyway (thus,
there should be no memory problem), but currently many computations
happen before trying to get stuff from the cache.

3. By #9138, matrix spaces make full use of the category framework.
However, initialisation with all category stuff takes much time, and
usually matrix spaces are just considered to be containers (so, one
wouldn't need categories). Hence, matrix space initialisation could be
reverted to its pre-9138 form. The price to pay: MatrixSpace(QQ,
3))._test_category() will fail.

4. Currently, weak references are used for caching matrix spaces. I
found that during J0(46).endomorphism_ring() .gens(), some matrix
spaces were garbage collected and then created again. I think some
people would complain if I'd use "strong" references for caching (so
that all matrix space would hang around forever). But perhaps one
could temporarily switch off garbage collection in some elliptic curve
methods?

Cheers,
Simon

[Simon King]

Hi!

On 6 Okt., 08:32, Simon King <simon.k...@uni-jena.de> wrote:
> Hi!
>
> I think I would be able to fix the regression, but I'd like to ask
> whether you would object to my approach.
>
> The ticket is #11900.

For the record: The patch at #11900 reduces the regressions
considerably, one test is now slightly faster than without #9138.

> 4. Currently, weak references are used for caching matrix spaces. I
> found that during J0(46).endomorphism_ring() .gens(), some matrix
> spaces were garbage collected and then created again. I think some
> people would complain if I'd use "strong" references for caching (so
> that all matrix space would hang around forever). But perhaps one
> could temporarily switch off garbage collection in some elliptic curve
> methods?

I did not use that method in my patch, yet. What do people think about
caching of matrix spaces resp. turning off garbage collection?

Cheers,
Simon

[Volker Braun]

If its just this one method, why not reference all matrix spaces in a local variable?

[Jeroen Demeyer]

On 2011-10-05 15:27, Jeroen Demeyer wrote:

Some updated timings below, all times are best-out-of-3 wall times, in
seconds. Patch #11900 is in progress so the timing is with the current
patch. "baseline" means sage-4.7.2.alpha3 without #9138. Clearly, the
slowdown of elltest2.sage is not due to #9138. Also Singular does not
cause a slowdown.

cyclomat.sage:
sage-4.7.2.alpha2: 6.9
baseline: 7.3
baseline + #9138 + #11900: 7.4
baseline + #11339 + #10903: 6.8

ellbsd.sage:
sage-4.7.2.alpha2: 7.5
baseline: 7.3
baseline + #9138 + #11900: 12.4
baseline + #11339 + #10903: 7.4

elltest1.sage:
sage-4.7.2.alpha2: 27.0
baseline: 24.4
baseline + #9138 + #11900: 31.7
baseline + #11339 + #10903: 24.7

elltest2.sage:
sage-4.7.2.alpha2: 19.6
baseline: 63.8
baseline + #9138 + #11900: 62.3
baseline + #11339 + #10903: 62.9

J0_46_disc.sage
sage-4.7.2.alpha2: 8.9
baseline: 8.2
baseline + #9138 + #11900: 8.8
baseline + #11339 + #10903: 8.4

[daveloeffler]

On Oct 6, 5:25 pm, Jeroen Demeyer <jdeme...@cage.ugent.be> wrote:

> Clearly, the
> slowdown of elltest2.sage is not due to #9138. Also Singular does not
> cause a slowdown.
>

I know what the problem is here -- see my post on sage-nt.

> elltest2.sage:
> sage-4.7.2.alpha2:          19.6
> baseline:                   63.8
> baseline + #9138 + #11900:  62.3
> baseline + #11339 + #10903: 62.9

David