sage_wraps should only read the sources of wrapped functions when needed.

[simon-king-jena]

According to private conversation with Francois Bissey, #9976 has introduced a problem that makes it impossible start sage-4.7.1 on Gentoo. That's pretty serious, and so this ticket is a blocker.

The problem is that sage_wraps reads the sources of to-be-wrapped functions and methods. The sources are stored as an attribute to the wrapper, which, on the one hand, is a waste of memory. Worse: Reading the Cython sources is impossible for sage-on-gentoo. Therefore, sage can't start.

My patch introduces some lightweight classes, that simply store a reference to an object (e.g., the to-be-wrapped function) and return the sources or source lines or the argument list only when called.

---

Apply only attachment: trac11734_sage_wraps_no_sourceread_lambda.proper.patch to the Sage library.

CC: @kiwifb

Component: misc

Keywords: sage_wraps sources gentoo startuptime sd32

Author: Julian Rueth

Reviewer: Simon King

Merged: sage-4.7.2.alpha3

Issue created by migration from https://trac.sagemath.org/ticket/11734

[simon-king-jena]

sage_wraps should only read source files when needed.

[simon-king-jena]

comment:1

Attachment: trac11734_sage_wraps_no_sourceread.patch.gz

The patch should solve the problem with prematurely reading sources on gentoo. However, I can not test it, myself. Francois, can you verify it?

Benefits

Startuptime

The startuptime did slightly improve (but perhaps that is not significant):

Without patch

$ ./sage -startuptime
== Tree ==
sage.all: 1.132 (None)
...

With patch

$ ./sage -startuptime
== Tree ==
sage.all: 1.045 (None)

Memory

The memory consumption improved as well:

Without patch:

sage: get_memory_usage()
861.2890625

With patch:

sage: get_memory_usage()
861.234375

Bugfix

Not reading the sources when a function is wrapped has an additional benefit: If one interactively defines a lambda function and wraps it, then the source is not available. Hence, the following example (that is a new doctest) used to fail:

        sage: def square(f):
        ...     @sage_wraps(f)
        ...     def new_f(x):
        ...         return f(x)*f(x)
        ...     return new_f
        ... 
        sage: f = lambda x:x^2
        sage: g = square(f)
        sage: g(3)
        81

Without the patch, the last line fails with a mysterious attribute error (the user would certainly have not easily been able to track the problem down).

[simon-king-jena]

Changed keywords from sage_wraps sources gentoo to sage_wraps sources gentoo startuptime

[saraedum]

comment:3

I do not fully understand your patch. How does it differ from simply taking out the call to sage_getargspec and moving it into a lambda? (see my attached patch)

Btw. On my install of sage-4.7.2alpha2 the doctest described in Bugfix does not fail.

[simon-king-jena]

comment:4

Replying to @saraedum:

I do not fully understand your patch. How does it differ from simply taking out the call to sage_getargspec and moving it into a lambda? (see my attached patch)

If I remember correctly, I once tried that approach. The line argspec = sage_getargspec(wrapped) was introduced for a reason (something went wrong), but I can't remember what it was.

Did you run full tests with your patch?

Btw. On my install of sage-4.7.2alpha2 the doctest described in Bugfix does not fail.

Really? Strange. It failed for me both with sage-4.7.2.alpha1 and with sage-4.6.2.

[simon-king-jena]

comment:5

The tests in sage/misc pass with your patch, and the example from my post above (the "bugfix") works as well.

If all tests pass, then you patch should be preferred.

It turned out that I am not to blame for the "argspec = sage_getargspec(wrapped)". The first author of #9976 had introduced an alternative approach to provide the argument list when building the documentation -- and I think what we have here is an artefact of that approach.

Since it was about documentation: Could you please build the documentation with your patch (I will only be able to do so tomorrow) and look whether the list of arguments of functions and methods created with @sage_wraps are correct in the reference manual? See, for example, the interreduced_basis method of multivariate polynomial ideals.

[simon-king-jena]

comment:6

PS: Even though the example from my previous post does not fail on your machine (for reasons that I don't understand), it did fail for me. Hence, I think it would make sense to include that example into your patch (you can of course simply copy the example from my patch).

[saraedum]

comment:7

I ran the doctests without long and they passed. Let me try to build the reference manual.

[saraedum]

comment:8

The reference manual seems ok. For example I get complete_primary_decomposition(algorithm='sy') which is a method with the * @libsingular_standard_options* decorator.

[simon-king-jena]

comment:9

I can confirm that the doc tests pass. I can also confirm that your patch provides a similar (small) positive side effect (comparable to what I stated on my patch) on startuptime and memory consumption.

Please add the above "bugfix" example to your patch. In the author field, please replace my name by yours.

[williamstein]

Changed keywords from sage_wraps sources gentoo startuptime to sage_wraps sources gentoo startuptime sd32

[kiwifb]

comment:11

Hi, I had to take a bit more rest than I expected - exhaustion is bad for you :)

I have just tested this patch in 4.7.2.alpha2 and it works. I think Simon has not made clear the fact that my original report was about the sage on gentoo distribution. It still meant that sage was looking at some cython files before starting up, which can't be good for the startup time.

[simon-king-jena]

comment:12

Replying to @kiwifb:

I have just tested this patch in 4.7.2.alpha2 and it works.

You mean, it would definitely fix the Gentoo problem?

I think Simon has not made clear the fact that my original report was about the sage on gentoo distribution.

The ticket description states "introduced a problem that makes it impossible start sage-4.7.1 on Gentoo." I thought that it is clear enough.

It still meant that sage was looking at some cython files before starting up, which can't be good for the startup time.

Yep. Actually I have tested (by inserting print statements in the functions that read the sources for auto-inspection) that no file is read at startup, with the patch.

[simon-king-jena]

comment:13

Concerning documentation: It looks very nice!

Just for testing, I had inserted a function with a complicated argument list, and put it under the @singular_standard_options decorator:

@singular_standard_options
def MyTestFunc(bla, blubb, bar={'bla':{1:2}}, foo=None, **kwds):
    """
    This is just a test
    """
    return

It is shown in the reference manual exactly as it should.

In addition, the doc tests pass, the startup time seems to slightly improve (perhaps not significantly), and the memory consumption decreases a little.

I hope I understood correctly that it will fix the problem on gentoo.

In general, if a bug is fixed, it should be demonstrated by a new doc test. The example that I gave above does fail (at least for me) without the patch. So, I think it should be included. If nobody beats me to it, I'd provide that example in a referee patch.

Also I don't know the real name of saraedum. So, please insert the name in the Author field.

Apart from that, it is a positive review.

[simon-king-jena]

Reviewer: Simon King

[simon-king-jena]

Changed author from Simon King to none

[saraedum]

Author: Julian Rueth

[saraedum]

comment:15

I'm not sure if I misunderstand what you mean to say with 'significantly' but the average startuptime does actually improve with that patch. (I would provide some data but can't reach the machine where that data is stored right now)

[simon-king-jena]

comment:16

Replying to @saraedum:

I'm not sure if I misunderstand what you mean to say with 'significantly'

There is the "sage -startuptime" script. It prints a lot of data, but the time for importing sage.all is most important, as much as I understood.

Without the patch, I get with sage-4.7.2.alpha2:

== Slowest (including children) ==
1.242 sage.all (None)

With the patch, I get:

Slowest (including children)

1.133 sage.all (None)
}}}

However, these times are a little flaky. So, I don't know if we can call it significant if the difference is 10%.

Concerning the additional test: It is a bit strange. It turned out that it does fail when I execute it on command line, but it does not fail (even without your patch) when it is a doc test. Apparently, in a doc test, Sage is able to find the function definition, which is impossible on the command line.

[saraedum]

comment:17

Anyway, I would leave the doctest in; probably we should add a comment, describing this difference.
Btw. I use dumbbench and a silenced version of startuptime to make sure that I'm not only seeing random speedups.

The speedup is actually a little bit mysterious. It occurs once you remove a few sage_wraps decorators. Apparently python's inspect.ArgSpec does something smart once it gets called very often (to speed up things?) which results in a slowdown in our case.

[simon-king-jena]

comment:18

Replying to @saraedum:

Anyway, I would leave the doctest in; probably we should add a comment, describing this difference.

OK, please do!

The speedup is actually a little bit mysterious. It occurs once you remove a few sage_wraps decorators. Apparently python's inspect.ArgSpec does something smart once it gets called very often (to speed up things?) which results in a slowdown in our case.

You removed a few sage_wraps for a test?

Actually I find the speedup not mysterious. The 10% are just with your patch, i.e., I did not additionally remove sage_wraps. And the reason for the speedup is clear: Python's inspect.getargspec is insufficient for Sage. It can not deal with Cython functions, and of course it can not understand the special wrappers in Sage:

sage: import inspect
sage: cython('cpdef f(a,b,c=None): pass')
sage: inspect.getargspec(f)
---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)

/mnt/local/king/SAGE/sage-4.7.2.alpha2/devel/sage-main/<ipython console> in <module>()

/mnt/local/king/SAGE/sage-4.7.2.alpha2/local/lib/python/inspect.pyc in getargspec(func)
    801         func = func.im_func
    802     if not isfunction(func):
--> 803         raise TypeError('arg is not a Python function')
    804     args, varargs, varkw = getargs(func.func_code)
    805     return ArgSpec(args, varargs, varkw, func.func_defaults)

TypeError: arg is not a Python function

and similarly

sage: P.<x,y,z> = QQ[]
sage: I = P*[x,y]
sage: inspect.getargspec(I.interreduced_basis)
ArgSpec(args=[], varargs='args', keywords='kwds', defaults=None)
sage: inspect.getargspec(I.groebner_basis)
---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)

/mnt/local/king/SAGE/sage-4.7.2.alpha2/devel/sage-main/<ipython console> in <module>()

/mnt/local/king/SAGE/sage-4.7.2.alpha2/local/lib/python/inspect.pyc in getargspec(func)
    801         func = func.im_func
    802     if not isfunction(func):
--> 803         raise TypeError('arg is not a Python function')
    804     args, varargs, varkw = getargs(func.func_code)
    805     return ArgSpec(args, varargs, varkw, func.func_defaults)

TypeError: arg is not a Python function

while the Sage autoinspection finds

sage: from sage.misc.sageinspect import sage_getargspec
sage: sage_getargspec(I.interreduced_basis)
ArgSpec(args=['self'], varargs=None, keywords=None, defaults=None)
sage: sage_getargspec(I.groebner_basis)
ArgSpec(args=['self', 'algorithm', 'deg_bound', 'mult_bound', 'prot'], varargs='args', keywords='kwds', defaults=('', None, None, False))

In the most difficult cases, sage_getargspec actually needs to read the source (using sage_getsourcelines) and analyse the function definition. That's why inspect.getargspec is faster (yet a lot less powerful) than sage.misc.sageinspect.sage_getargspec.

[saraedum]

comment:19

I spend quite a bit of time looking at that speedup yesterday. While everything you say is certainly correct, a big part comes from calling the constructor I mentioned less frequently. It turned out that removing the decorator from any interacts control would almost yield the same speedup - even though the that control is never referenced in the --startuptime call.
If I trust cProfile then there is a single call to the ArgSpec constructor that is slow after a certain number of calls. Maybe cProfile is misleading here, and actually something else is happening...anyway, it's faster now, I don't think it introduces any new bug, so I'm happy with the result ;)

[simon-king-jena]

comment:20

Attachment: trac11734_sage_wraps_no_sourceread_lambda.patch.gz

With the new patch, all tests pass, and for the reasons mentioned previously it is a positive review.

[simon-king-jena]

comment:22

For the patchbot:

Apply trac11734_sage_wraps_no_sourceread_lambda.patch

[nexttime]

Merged: sage-4.7.2.alpha3

[nexttime]

Attachment: trac11734_sage_wraps_no_sourceread_lambda.proper.patch.gz

"Proper" Mercurial changeset replacement patch.

[nexttime]

comment:24

I've attached a *.proper.patch, which is identical except that I removed the "garbage" before "# HG changeset patch", i.e., I deleted the first line "exporting patch:", since Jeroen's current merger rejects such patches.

For now, please make sure all your patches start with "# HG changeset patch", i.e., have it on the first line without any preceding messages or whatever.

I've relaxed that in my version of the merger, but Jeroen and maybe others are likely to use his more restrictive one.