sage startup time hasn't improved...

[William Stein]

Hi,

I'm sad that on a fast SSD repeatedly doing the following:

wstein@geom:/usr/local/sage/sage-5.2$ time echo "" | ./sage
----------------------------------------------------------------------
| Sage Version 5.2, Release Date: 2012-07-25 |
| Type "notebook()" for the browser-based notebook interface. |
| Type "help()" for help. |
----------------------------------------------------------------------
sage: sage:
Exiting Sage (CPU time 0m0.03s, Wall time 0m0.03s).

real 0m1.902s
user 0m1.428s
sys 0m0.424s

always outputs 1.9 seconds! That test was < 1 second on sage.math
when I put in a doctest to make sure it didn't exceed that 1 second,
when we were trying to improve the sage startup time. In the
intervening year (?), the test is ignored or gone, and the startup
time seems to have got a bit worse. Dang.

On another faster machine, I'm getting:

wstein@combinat:/usr/local/sage/sage-5.2$ time echo "" | ./sage
----------------------------------------------------------------------
| Sage Version 5.2, Release Date: 2012-07-25 |
| Type "notebook()" for the browser-based notebook interface. |
| Type "help()" for help. |
----------------------------------------------------------------------
sage: sage:
Exiting Sage (CPU time 0m0.04s, Wall time 0m0.05s).

real 0m1.580s
user 0m1.224s
sys 0m0.356s


Any ideas?




William




--
William Stein
Professor of Mathematics
University of Washington
http://wstein.org

[Volker Braun]

Which file system and mount options are you using? These numbers sound a tad too long.

On my laptop (SSD, but with warm cache, so it doesn't matter):

[vbraun@laptop ~]$ time echo "" | sage 

----------------------------------------------------------------------

| Sage Version 5.3.beta0, Release Date: 2012-08-01                   |

| Type "notebook()" for the browser-based notebook interface.        |

| Type "help()" for help.                                            |

----------------------------------------------------------------------

**********************************************************************

*                                                                    *

* Warning: this is a prerelease version, and it may be unstable.     *

*                                                                    *

**********************************************************************

sage: sage: 

Exiting Sage (CPU time 0m0.05s, Wall time 0m0.05s).

real 0m0.986s

user 0m0.765s

sys 0m0.219s

On sagepad.org (hdd, inside a kvm virtual machine):

[sagebuilder@backend sage-5.2]$ time echo "" | ./sage 

----------------------------------------------------------------------

| Sage Version 5.2, Release Date: 2012-07-25                         |

| Type "notebook()" for the browser-based notebook interface.        |

| Type "help()" for help.                                            |

----------------------------------------------------------------------

sage: sage: 

Exiting Sage (CPU time 0m0.02s, Wall time 0m0.07s).

real 0m1.179s

user 0m0.927s

sys 0m0.218s

[Volker Braun]

PS: not really fair since my desktop ivy bridge has better single-thread performance than a server, but oh well:

[vbraun@volker-desktop ~]$ time echo "" | sage

----------------------------------------------------------------------

| Sage Version 5.1.rc1, Release Date: 2012-07-05                     |

| Type "notebook()" for the browser-based notebook interface.        |

| Type "help()" for help.                                            |

----------------------------------------------------------------------

**********************************************************************

*                                                                    *

* Warning: this is a prerelease version, and it may be unstable.     *

*                                                                    *

**********************************************************************

sage: sage: 

Exiting Sage (CPU time 0m0.01s, Wall time 0m0.01s).

real 0m0.649s

user 0m0.522s

sys 0m0.128s

[Benjamin Jones]

Another data point: I also get (just barely) under 1s on a ~1 year old
server running debian 6.0.5.

<pre>
jonesbe@sage:~/sage/sage-5.2$ time echo "" | ./sage

----------------------------------------------------------------------
| Sage Version 5.2, Release Date: 2012-07-25 |
| Type "notebook()" for the browser-based notebook interface. |
| Type "help()" for help. |
----------------------------------------------------------------------

Loading Sage library. Current Mercurial branch is: 11143
sage: sage:
Exiting Sage (CPU time 0m0.02s, Wall time 0m0.02s).

real 0m0.977s
user 0m0.676s
sys 0m0.300s
</pre>

This is a VM running on Intel(R) Xeon(R) CPU X5690 @ 3.47GHz and
RAID-5 server grade hard drives. Mount options:

<pre>
/dev/xvda4 on /home type ext3
(rw,nosuid,nodev,relatime,errors=continue,data=ordered)
</pre>


--
Benjamin Jones

[Volker Braun]

I'm using basically the same mount options on ext4. E.g laptop:

/dev/sda5 on /home type ext4 (rw,relatime,seclabel,data=ordered)

[Andrea Lazzarotto]

Did you try to enable TRIM to see if it makes a difference?

Andrea Lazzarotto
(inviato da Android)

[Volker Braun]

TRIM is about write performance, it does nothing whatsoever for reading from cache.

[Robert Bradshaw]

This is really frustrating. I find myself using (I)Python when I would
have used Sage sometimes just because it takes too long to start up.

It looks like the time was bumped up a year and a half ago:
http://trac.sagemath.org/sage_trac/ticket/10614

There are some fundamental restrictions of LazyImport with respect to
instances created at startup time, but it works great for functions. I
think sage.schemes.all (320 ms) and sage.plot.all (100ms) are good
candidates for this.

Overall, I think it's basically it's everyone being aware that when
they import something into the global namespace, there is a startup
time cost. It's probably much smaller than the variance for most
tickets, or it would be interesting to try to detect this. We could
add a plugin to the patchbot to list *new* modules imported at startup
by examining sys.modules.

- Robert

[Volker Braun]

I still don't understand why its so slow for you, on a recent machine Sage startup with warm cache should be around 1s.  

Playing around with the startup a bit, I noticed that the notebook stuff imports a lot during startup. Why do we need to import anything from the notebook except the notebook() function? This seems wasteful. Cutting out the notebook imports saves me about 1/4 of the startup time (from ~1s to 0.75s).

We also have a lot of stuff in the sys.path that causes many failed open() calls upon startup as Python has to check every directory for modules. About half of all are notebook-related python packages that have no use in mathematics. These are also subdirectories of site-packages so they are searched twice since site-packages is also is sys.path. Just getting rid of packages that are only used in the notebook saves about a third of all open() calls during startup. But on my laptop that only saves something on the order of 0.01s, basically nothing. But if you have a slow file system then it might make a difference.

On Friday, August 10, 2012 8:51:17 PM UTC-4, William wrote:

[Ivan Andrus]

I get around 2 seconds on my MacBook Pro (non-SSD) that's a couple years old.  FWIW, sage -c is consistently 10% faster than `echo "" | sage`.

$ time sage -c 'print 3+2'

5

real 0m1.809s

user 0m1.158s

sys 0m0.705s

$ time echo "" | sage

----------------------------------------------------------------------

| Sage Version 5.2, Release Date: 2012-07-25                         |

| Type "notebook()" for the browser-based notebook interface.        |

| Type "help()" for help.                                            |

----------------------------------------------------------------------

sage: sage: 

Exiting Sage (CPU time 0m0.05s, Wall time 0m0.05s).

real 0m2.001s

user 0m1.312s

sys 0m0.750s

I think we either need to make startup time a hard and fast rule for reviewing—which means we need an easy and consistent way to test—or we just forget about it and use something like sage-forker (except probably based on the new ipython).  I think the latter is going to give better performance, but startup time might still be important for other reasons that I'm not thinking of.  

-Ivan

--
--
To post to this group, send an email to sage-...@googlegroups.com
To unsubscribe from this group, send an email to sage-devel+...@googlegroups.com
For more options, visit this group at http://groups.google.com/group/sage-devel
URL: http://www.sagemath.org
 
 
 

[Volker Braun]

To understand the impact of failed module loads (where Python traverses sys.path looking for a module), I used the following code:

import string

import random

def random_string(n):

    return ''.join(random.choice(string.ascii_letters) for x in range(n))

    

def random_import():

    for i in range(100):

        name = random_string(5)+'.'+random_string(5)+'.'+random_string(5)

        try:

            __import__(name)

        except ImportError:

            pass

On geom.math:

sage: %timeit random_import()

5 loops, best of 3: 175 ms per loop

On my laptop:

sage: %timeit random_import()

5 loops, best of 3: 47.1 ms per loop

This is both times with warm cache. I also tried enabling the atime mount option on my laptop, and that did not cause any noticeable changes. I also tried some background CPU load on my laptop, and as long as I don't saturate all cores I find only minor (~10%) slowdown. So its mysterious to me why geom.math is so slow. It would would be interesting to know how geom.math benchmarks when it is completely idle, right now its at about 50% CPU load. 

[Jeroen Demeyer]

Best-out-of-30 startup times for various versions on sage.math in /home
(mounted over NFS):

sage-4.6: 2.4s
sage-4.7: 2.5s
sage-4.8: 2.5s
sage-5.0.1: 2.2s
sage-5.2: 2.7s

It seems sage-5.0 saw an improvement (I guess due to Python-2.7), but it
got worse again. I'll try to add some data points between sage-5.0.1
and sage-5.2 to see where things went wrong.

[Volker Braun]

I've patched sage -startuptime to report and sort by time excluding children, see http://trac.sagemath.org/13361 (needs review):

== Slowest module imports (excluding / including children) ==

exclude/ms include/ms   #parents  module name

     1.737      1.795          2  sage.libs.ppl

     1.749      1.752          9  urlparse

     1.835     15.190          8  sage.calculus.calculus

     1.844      2.506          1  email.utils

     1.850      1.976          1  sage.sandpiles.sandpile

     1.861      1.917          2  sage.combinat.sf.macdonald

     1.869      1.873          4  pickle

     1.909      9.049         13  sage.rings.number_field.number_field

     1.935      8.447          5  sage.libs.singular.singular

     1.985      1.990          1  Cookie

     1.994     65.088          1  sagenb.notebook

     2.050      2.410         10  jinja2.utils

     2.079     15.447          8  jinja2

     2.164      3.237          3  zmq.core

     2.214      2.229          4  sage.interfaces.maxima

     2.226      2.238          2  jinja2.lexer

     2.470      2.657          9  sage.interfaces.singular

     2.494      9.581         10  sage.rings.polynomial.multi_polynomial_libsingular

     2.562      3.764          2  werkzeug.routing

     2.604      2.645          1  sage.combinat.words.paths

     2.607     41.060          2  sage.graphs.generic_graph

     2.709     16.778         12  sage.functions.other

     2.799      2.799          2  _ssl

     3.181     19.026         26  inspect

     3.211      3.592          3  sage.schemes.elliptic_curves.heegner

     3.271      3.271          1  sage.ext.c_lib

     3.279     47.423         14  IPython

     3.349     19.990          8  sage.rings.quotient_ring

     3.358      3.594          6  sage.interacts.library

     3.596      7.450         25  sage.libs.pari.gen

     3.618      3.634          1  doctest

     3.627      3.711          1  sage.libs.cremona.newforms

     3.914      5.606        218  sage.misc.sageinspect

     4.003      4.055          1  sage.combinat.sloane_functions

     4.075     49.647         12  sage.rings.complex_double

     4.225      4.229          2  platform

     4.274      4.378          2  sage.libs.linbox.linbox

     4.318      4.887          3  sage.matrix.matrix_mod2_dense

     4.441      5.168          1  decimal

     4.685      4.978          1  sage.misc.latex_macros

     5.224      8.063        218  sage.structure.element

     5.744      8.285          4  sage.rings.polynomial.pbori

     7.909     17.876          4  sage.rings.qqbar

    10.937     11.211          6  tokenize

    11.508     12.061          3  pytz

    16.608     29.729         15  sage.groups.perm_gps.permgroup

    43.575     43.648          6  pkg_resources

    45.088     45.090          4  flaskext.babel

    50.665    741.180          4  sage.all

    53.833    342.815        239  sage

Total time (sum over exclusive time): 786.690ms

[Jeroen Demeyer]

Second measurement, best-out-of-10 on sage.math (less loaded than
previous time), using /home:

sage-4.6: 2.4s
sage-4.7: 2.5s
sage-4.8: 2.4s
sage-5.0.1: 2.0s
sage-5.1: 2.1s
sage-5.2: 2.7s

So, I would say there was a measurable speed-up in sage-5.0 and a more
serious slow-down in sage-5.2.

[Volker Braun]

For comparison, here is sage-5.1.rc1. It looks like the notebook update pulled in two slow modules: flaskext.babel and pytz. And we now have a longer sys.path (from 26 to 39 entries), which makes module loading overall slower. Especially since the filesystem is 4x slower than on my laptop for some reason.

[vbraun@laptop sage-5.1.rc1]$ ./sage -startuptime

== Slowest module imports (excluding / including children) ==

exclude/ms include/ms   #parents  module name

     1.583     10.143          1  sage.calculus.desolvers

     1.613      1.930          1  httplib

     1.639      1.911         22  string

     1.727      1.730          5  urlparse

     1.732      1.737          3  pickle

     1.755     18.179          1  IPython.Shell

     1.788      2.001          8  sage.symbolic.constants

     1.807      9.756         13  sage.rings.number_field.number_field

     1.862      1.866        150  sage.structure.generators

     1.866      2.220         10  jinja2.utils

     1.953     14.244          5  jinja2

     2.097      9.478          5  sage.libs.singular.singular

     2.119     14.740        192  sage.rings.integer

     2.123      4.326          2  sage.monoids.all

     2.198     18.640          7  sage.calculus.calculus

     2.210      2.278          2  sage.combinat.sf.macdonald

     2.242      2.254          2  jinja2.lexer

     2.353      2.728          3  sage.schemes.elliptic_curves.heegner

     2.488     14.270         16  sage.combinat.permutation

     2.491      2.751          9  sage.interfaces.singular

     2.716     44.095          2  sage.graphs.generic_graph

     2.754      2.793          1  sage.combinat.words.paths

     2.856      2.926          2  sage.libs.ppl

     3.136     38.274         12  sage.functions.other

     3.211      3.480          6  sage.interacts.library

     3.230     18.647         26  inspect

     3.419      3.472          1  sage.combinat.sloane_functions

     3.579      3.579          2  _ssl

     3.597     22.176          8  sage.rings.quotient_ring

     3.605     46.924         14  IPython

     3.610      3.620          1  doctest

     3.688     11.747          4  twisted.python

     3.935      8.098         25  sage.libs.pari.gen

     3.999      4.002          2  platform

     4.112      5.951        213  sage.misc.sageinspect

     4.370     12.454         10  sage.rings.polynomial.multi_polynomial_libsingular

     4.808      4.942          3  sage.libs.linbox.linbox

     5.005      5.679          3  sage.matrix.matrix_mod2_dense

     5.052      5.158          1  sage.libs.cremona.newforms

     5.414      5.741          1  sage.misc.latex_macros

     5.638     55.698         12  sage.rings.complex_double

     5.925      8.790        217  sage.structure.element

     6.121      6.121          1  sage.ext.c_lib

     8.673     21.573          4  sage.rings.qqbar

     8.807     13.434          4  sage.rings.polynomial.pbori

    11.047     11.262          6  tokenize

    16.645     30.675         18  sage.functions.all

    18.689    692.530          3  sage.all

    24.355     25.138          4  pkg_resources

    60.267    418.274        239  sage

Total time (sum over exclusive time): 693.063ms

[Mike Hansen]

On Sun, Aug 12, 2012 at 12:51 PM, Volker Braun <vbrau...@gmail.com> wrote:
> For comparison, here is sage-5.1.rc1. It looks like the notebook update
> pulled in two slow modules: flaskext.babel and pytz. And we now have a
> longer sys.path (from 26 to 39 entries), which makes module loading overall
> slower. Especially since the filesystem is 4x slower than on my laptop for
> some reason.

One easy improvement is to use pip instead of setuptools so that
things aren't added to sys.path when installing modules -- they're
just put directly in site-packages. We should also be able to
restructure notebook imports so as not to have to pull in
flaskext.babel and pytz.

--Mike

[Volker Braun]

I would propose that we go one step further:

  * Install all notebook dependencies into a separate directory

  * only import notebook() from the sagenb on startup

  * The notebook() function adds notebook dependencies to sys.path before importing its prerequisites

This would force the notebook to be modular and separate from the sage library. You would be able to run the sage commandline without openssl, for example.

[Keshav Kini]

Volker Braun <vbrau...@gmail.com> writes:
> I would propose that we go one step further:
>
> * Install all notebook dependencies into a separate directory
> * only import notebook() from the sagenb on startup
> * The notebook() function adds notebook dependencies to sys.path
> before importing its prerequisites
>
> This would force the notebook to be modular and separate from the
> sage library. You would be able to run the sage commandline without
> openssl, for example.

We already maintain a Python installation separate from the system
Python. Now you want to keep some of our python packages in yet another
location? Is that really necessary? I don't see why in order to make
certain modules not import on startup they must be physically moved
elsewhere. Or is the problem that Python is taking too long to even scan
the site-packages directory?

-Keshav

----
Join us in #sagemath on irc.freenode.net !

[Volker Braun]

On Monday, August 13, 2012 10:04:26 AM UTC-4, Keshav Kini wrote:

We already maintain a Python installation separate from the system
Python. Now you want to keep some of our python packages in yet another
location? Is that really necessary?

Its not really necessary, but it'll force the sage library (excluding notebook) to not import any modules that are prerequisites for the notebook only. More of a psychological than a technical necessity.

[Robert Bradshaw]

Shouldn't everything needed by the sage notebook (already) be in
sagenb.* anyways? This should be fairly explicit, no need to move
things around further. +1 to only importing notebook() (which lazily
loads what is needed on being called).

[Volker Braun]

On Monday, August 13, 2012 11:36:33 AM UTC-4, Robert Bradshaw wrote:

Shouldn't everything needed by the sage notebook (already) be in
sagenb.* anyways?

Yes, but thats not what I mean. For example, right now we import sage.graphs.graph_editor upon startup. And the graph editor imports the sage notebook. If the dependencies of the sage notebook were not in sys.path by default then this wouldn't have been possible to start with. 

[Robert Bradshaw]

Yeah, the import graph is pure spaghetti...

I am all for making tests that certain modules are *not* imported at
sage startup time which can help with more than just the notebook.
This seems more explicit and simpler than installing things in
different locations.

- Robert

[Volker Braun]

Doctests that ensure that certain modules are not imported upon startup are also fine with me. 

In any case, here is another data point. Interestingly, os.path.join is about as fast as posix.lstat. I'd take that as another piece of evidence that filesystem caches are incredibly well optimized.

[vbraun@laptop ~]$ sage -ipython

Python 2.7.3 (default, Aug  2 2012, 12:23:48) 

Type "copyright", "credits" or "license" for more information.

IPython 0.10.2 -- An enhanced Interactive Python.

?         -> Introduction and overview of IPython's features.

%quickref -> Quick reference.

help      -> Python's own help system.

object?   -> Details about 'object'. ?object also works, ?? prints more.

In [1]: import gc

In [2]: gc.disable()

In [3]: %prun from sage.all import *

         186078 function calls (180912 primitive calls) in 0.584 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)

       60    0.044    0.001    0.551    0.009 all.py:1(<module>)

        1    0.019    0.019    0.020    0.020 matrix_space.py:25(<module>)

        1    0.019    0.019    0.585    0.585 all.py:20(<module>)

       18    0.014    0.001    0.301    0.017 all.py:3(<module>)

      107    0.011    0.000    0.215    0.002 __init__.py:1(<module>)

     3046    0.010    0.000    0.014    0.000 posixpath.py:60(join)

        1    0.009    0.009    0.066    0.066 functional.py:13(<module>)

      164    0.008    0.000    0.008    0.000 dynamic_class.py:259(dynamic_class_internal)

  413/135    0.008    0.000    0.021    0.000 sre_parse.py:379(_parse)

        2    0.006    0.003    0.014    0.007 all.py:7(<module>)

  501/500    0.005    0.000    0.010    0.000 sageinspect.py:917(sage_getargspec)

     5908    0.005    0.000    0.006    0.000 sre_parse.py:182(__next)

  738/133    0.005    0.000    0.014    0.000 sre_compile.py:32(_compile)

     2206    0.005    0.000    0.005    0.000 {posix.lstat}

        1    0.004    0.004    0.010    0.010 interface.py:22(<module>)

  546/195    0.004    0.000    0.016    0.000 lazy_attribute.py:506(__get__)

      238    0.004    0.000    0.006    0.000 sre_compile.py:207(_optimize_charset)

  265/256    0.004    0.000    0.027    0.000 posixpath.py:355(realpath)

        1    0.004    0.004    0.011    0.011 infinity.py:191(<module>)

        1    0.004    0.004    0.004    0.004 ell_modular_symbols.py:37(<module>)

        3    0.004    0.001    0.011    0.004 polynomial_ring_constructor.py:507(_multi_variate)

        3    0.004    0.001    0.006    0.002 sequence.py:86(Sequence)

        2    0.003    0.002    0.007    0.003 all.py:4(<module>)

        1    0.003    0.003    0.047    0.047 cone.py:185(<module>)

 1029/432    0.003    0.000    0.004    0.000 sre_parse.py:140(getwidth)

     8686    0.003    0.000    0.003    0.000 {isinstance}

      282    0.003    0.000    0.003    0.000 {dir}

      815    0.003    0.000    0.003    0.000 {posix.stat}

    15703    0.003    0.000    0.003    0.000 {method 'startswith' of 'str' objects}

        1    0.003    0.003    0.006    0.006 number_field.py:70(<module>)

      621    0.003    0.000    0.003    0.000 {open}

        2    0.003    0.001    0.017    0.009 __init__.py:9(<module>)

        1    0.003    0.003    0.005    0.005 cubegroup.py:85(<module>)

        1    0.003    0.003    0.003    0.003 padic_extension_leaves.py:10(<module>)

    16444    0.003    0.000    0.003    0.000 {method 'endswith' of 'str' objects}

      142    0.002    0.000    0.007    0.000 homset.py:296(__init__)

      178    0.002    0.000    0.015    0.000 pkg_resources.py:1687(find_on_path)

      575    0.002    0.000    0.011    0.000 __init__.py:84(open_resource)

        1    0.002    0.002    0.014    0.014 constructor.py:137(<module>)

       25    0.002    0.000    0.002    0.000 {posix.listdir}

        1    0.002    0.002    0.002    0.002 paths.py:165(<module>)

   115/93    0.002    0.000    0.003    0.000 complex_interval_field.py:261(__call__)

      500    0.002    0.000    0.003    0.000 inspect.py:743(getargs)

        1    0.002    0.002    0.005    0.005 ambient.py:56(<module>)

     2206    0.002    0.000    0.008    0.000 posixpath.py:130(islink)

        1    0.002    0.002    0.008    0.008 support.py:9(<module>)

        1    0.002    0.002    0.002    0.002 sloane_functions.py:67(<module>)

     5132    0.002    0.000    0.007    0.000 sre_parse.py:201(get)

   100/98    0.002    0.000    0.040    0.000 homset.py:40(Hom)

        1    0.002    0.002    0.025    0.025 digraph.py:91(<module>)

        6    0.002    0.000    0.185    0.031 all.py:2(<module>)

[Jeroen Demeyer]

On 2012-08-14 02:07, Volker Braun wrote:
> In any case, here is another data point. Interestingly, os.path.join is
> about as fast as posix.lstat. I'd take that as another piece of evidence
> that filesystem caches are incredibly well optimized.

What measure of "time" is this using? Unless it's wall time, your table
below doesn't prove anything.

[Volker Braun]

On Tuesday, August 14, 2012 2:05:25 AM UTC-4, Jeroen Demeyer wrote:

What measure of "time" is this using?  Unless it's wall time, your table
below doesn't prove anything.

The python profiler measures wall time. Indeed this is the quantity that you usually want to minimize, so its just common sense.