Report startuptime exclusive children

[vbraun]

Right now sage -startuptime reports startup time including children. This isn't particularly useful since that just means that the first module (which loads most of sage as dependencies) is the slowest. The more meaningful number is exclusive children, which can tell us if the module does computations during initialization.

• Apply trac_13361_startuptime.patch​ to the scripts (SAGE_LOCAL/bin) repository.
• Apply trac_13361_startuptime_args.patch​ and trac_13361-root-referee.patch​ to the root repository.
• Apply trac_13361_fix_test.patch​ and trac_13361-sagelib-referee.patch​ to the Sage library

[vbraun]

Initial patch

[vbraun]

Initial patch

[vbraun]

Now with disabled garbage collector (it did skew timings) and with optional argument a module that you want to know more about:

[vbraun@laptop sage]$ sage -startuptime sage.geometry.fan

========================================================================
== Slowest modules importing sage.geometry.fan =========================
exclude/ms include/ms   #parents  module name
     0.115     51.405          3  sage.geometry.all
     0.224      0.246          1  sage.schemes.toric.library
     0.332      0.398          1  sage.geometry.triangulation.fan_refinement
     0.383      0.471          2  sage.geometry.fan_morphism
     0.560      0.782          3  sage.schemes.toric.variety

== Slowest modules imported by sage.geometry.fan =======================
exclude/ms include/ms   #parents  module name
     0.533      2.509         19  collections
     0.607     67.336          5  sage.combinat.posets.posets
     0.631    140.774         51  sage.misc.all
     0.734     49.422          5  sage.geometry.cone
     0.772      2.777          4  sage.geometry.lattice_polytope
     1.121      1.124        175  sage.misc.abstract_method
     1.247      1.247        180  sage.misc.lazy_attribute
     1.304     65.086        230  sage.rings.all
     1.332      1.332         63  copy
     3.837      5.491        218  sage.misc.sageinspect

== module sage.geometry.fan ============================================
Time to import:  0.751ms
Cumulative time: 0.823ms
Names: fan, sage.geometry.fan

[vbraun]

Improved patch

[vbraun]

New patch has better handling of ambiguous command line argument and prints module file.

[vbraun]

Initial patch

[jhpalmieri]

Two questions:

• would it be useful to be able to sort by times including children (keeping the default as is) by specifying a command-line argument? (I don't know the answer to this one.)

• should the usage sage --startuptime [modulename] be documented in sage --advanced and in devel/sage/doc/en/reference/options.rst? (I think the answer to this one is "yes". See the attached referee patches.)

[jhpalmieri]

root repo: documentation

[vbraun]

I don't think there is much point in the inclusive startup time, that just tells you which library was imported first (and then pulled in a lot of sage modules for the first time). Thats why the old startuptime always showed a ridiculously long time for sage.algebras.iwahori_hecke_algebra despite this being a very lightweight module.

Thanks for the referee patches, they look great!

[jhpalmieri]

Oops, we missed one thing: the test in tests/startup.py has to be rewritten to take into account the changed output of sage --startuptime. (This will only make a difference when testing on sage.math.)

[jhpalmieri]

I've added to my referee's patch to fix the doctest in tests/startup.py. Also, now if the test fails, it prints how long sage --startuptime took, instead of just returning False.

[jhpalmieri]

Sage library: documentation and doctest fix

[vbraun]

Hmm a hostname-dependent doctest ;-)

Thanks for the patch, looks good!