Bug in sage -startuptime?

[Simon King]

Hi!

The patchbot's startup_time plugin complains about #14159. In order to
see what is happening, I studied the output of sage -startuptime, and
got a surprise.

I have run `sage -startuptime` both with and without the patch.

- Without the patch, the import of `_ssl` is listed with 3.397ms. But
with the patch, `_ssl` is not listed.
- With the patch, the import of `sage.plot.graphics` is listed with
21.036ms. But without the patch, `sage.plot.graphics` is not listed.

I can neither believe that `sage.plot.graphics` is not imported during
startup in vanilla sage, nor can I believe that `sage.plot.graphics` is
only imported since the intestines of coercion dictionaries change.

Bug in the startuptime script? Or how can it be explained that
sage.plot.graphics was not listed for vanilla sage?

Best regards,
Simon

[Nils Bruin]

On Feb 26, 11:32 pm, Simon King <simon.k...@uni-jena.de> wrote:
> Hi!
>
> The patchbot's startup_time plugin complains about #14159. In order to
> see what is happening, I studied the output of sage -startuptime, and
> got a surprise.

I don't think the list printed is complete. It seems to be just a top
50. It probably means that _ssl got pushed out of the top 50 and that
sage.plot.graphics just came in. You can get more info with "sage -
startuptime sage.plot.graphics" with either. It might be interesting
to compare the results.

[Volker Braun]

First of all, the "sage -startuptime" and the patchbot startuptime module are totally independent. 

The output of "sage -startuptime" only lists the 50 slowest modules, not all. There is also a certain amount of luck in its output for individual modules, e.g. whether or not the globals() hash table is reallocated during the module import. Garbage collection is turned off, at least.

[Simon King]

Hi Volker,

On 2013-02-27, Volker Braun <vbrau...@gmail.com> wrote:
> The output of "sage -startuptime" only lists the 50 slowest modules, not
> all.

OK. But *with* the patch, sage.plot.graphics is the 6th slowest module,
and much much slower than _ssl, for example---but _ssl is among the 50
slowest modules *without* the patch.

I can hardly imagine that the timings are so extremely unstable (we are
talking about > 20ms versus < 3.4ms). But perhaps they are: When I repeated
sage -startuptime now, it sage.plot.graphics showed up without the patch.

Cheers,
Simon

[Robert Bradshaw]

I can attest that the timings are extremely unstable with regard to
what's imported where and their order. For example, why does sage.misc
take so long? Because it imports nearly half of sage.rings. Later
modules will be fast or slow depending on what's been sucked in
earlier. This is one of the reasons it's so hard to debug circular
imports and startup time.
https://plus.google.com/106060403099461455118/posts/KhGipCThNtN
http://trac.sagemath.org/sage_trac/attachment/ticket/11749/11749-unneeded-imports.patch#01155b7d76b047a334c460569e9e8c54
http://trac.sagemath.org/sage_trac/ticket/11762

- Robert

[Volker Braun]

The new "sage -startuptime" is supposed to do the accounting correctly, that is, only count the time spent importing the current module. Though of course adding stuff to dicts is not constant time and does depend on ordering...