Opened 11 years ago
Closed 10 years ago
#13057 closed defect (fixed)
introspection is slow and causes a significant memory leak
Reported by:  Jonathan Bober  Owned by:  Minh Van Nguyen 

Priority:  critical  Milestone:  sage5.1 
Component:  documentation  Keywords:  regression introspection 
Cc:  Florent Hivert  Merged in:  sage5.1.beta5 
Authors:  John Palmieri  Reviewers:  Keshav Kini 
Report Upstream:  N/A  Work issues:  
Branch:  Commit:  
Dependencies:  Stopgaps: 
Description
Introspection used to be more or less immediate, and now something like
sage: gcd?<ENTER>
in the sage command line takes a few seconds.
"used to be" means that this slowdown happened sometime between 4.7.1 and 5.0, and probably between 4.8 and 5.0.
I don't know right now if we have the same regression in the notebook.
Attachments (1)
Change History (31)
comment:1 Changed 11 years ago by
comment:2 followup: 3 Changed 11 years ago by
I did
sage: from sage.misc.sageinspect import sage_getdoc sage: %prun L = sage_getdoc(gcd)
which, I thought, should reveal what is happening under the hood.
However, I don't really understand the outcome:
ncalls tottime percall cumtime percall filename:lineno(function) 1 0.286 0.286 1.269 1.269 intersphinx.py:74(read_inventory_v2) 20751 0.272 0.000 0.576 0.000 intersphinx.py:90(split_lines) 28708 0.215 0.000 0.327 0.000 posixpath.py:60(join) 2 0.179 0.089 0.179 0.090 {cPickle.dump} 73 0.123 0.002 0.123 0.002 {method 'search' of '_sre.SRE_Pattern' objects} 1 0.108 0.108 0.536 0.536 intersphinx.py:53(read_inventory_v1) 36194 0.099 0.000 0.099 0.000 {method 'setdefault' of 'dict' objects} 81003/79947 0.097 0.000 0.100 0.000 {len} 20758 0.095 0.000 0.246 0.000 {method 'decode' of 'str' objects} 26193 0.093 0.000 0.093 0.000 {_codecs.utf_8_decode} 1461/328 0.089 0.000 0.356 0.001 sre_parse.py:379(_parse) 7914 0.089 0.000 0.252 0.000 codecs.py:503(readline) 20238 0.086 0.000 0.125 0.000 sre_parse.py:182(__next) 2972/1056 0.084 0.000 0.093 0.000 sre_parse.py:140(getwidth) 28718 0.077 0.000 0.077 0.000 {method 'split' of 'unicode' objects} 20756 0.076 0.000 0.151 0.000 utf_8.py:15(decode) 5444 0.066 0.000 0.115 0.000 codecs.py:424(read) 29 0.064 0.002 0.118 0.004 sre_compile.py:301(_optimize_unicode) 2344/286 0.060 0.000 0.259 0.001 sre_compile.py:32(_compile) 28665 0.059 0.000 0.059 0.000 {method 'startswith' of 'unicode' objects} 18416 0.057 0.000 0.057 0.000 {method 'read' of 'file' objects} 26193 0.053 0.000 0.053 0.000 {method 'endswith' of 'unicode' objects} 28717 0.052 0.000 0.052 0.000 {method 'endswith' of 'str' objects} 41439 0.049 0.000 0.049 0.000 {method 'append' of 'list' objects} 28826 0.048 0.000 0.048 0.000 {method 'rstrip' of 'unicode' objects} 17769 0.045 0.000 0.154 0.000 sre_parse.py:201(get) 21097 0.045 0.000 0.045 0.000 {method 'find' of 'str' objects} 688 0.034 0.000 0.174 0.000 sre_compile.py:207(_optimize_charset) 7914 0.034 0.000 0.286 0.000 codecs.py:612(next) 10021 0.030 0.000 0.046 0.000 sre_parse.py:130(__getitem__) 1 0.027 0.027 0.115 0.115 pickle.py:845(load) 266 0.021 0.000 0.025 0.000 sre_compile.py:258(_mk_bitmap) 13462 0.021 0.000 0.021 0.000 {isinstance} 2766 0.017 0.000 0.030 0.000 pickle.py:929(load_binint1) 5499 0.015 0.000 0.015 0.000 {method 'splitlines' of 'unicode' objects} 918/288 0.015 0.000 0.361 0.001 sre_parse.py:301(_parse_sub) 7445 0.014 0.000 0.028 0.000 sre_parse.py:195(match) 23 0.013 0.001 0.013 0.001 {builtin method decompress} 4694 0.012 0.000 0.018 0.000 sre_parse.py:138(append) 1379 0.011 0.000 0.019 0.000 pickle.py:1173(load_long_binput) 8237 0.010 0.000 0.010 0.000 {ord} 66 0.009 0.000 0.015 0.000 optparse.py:1007(add_option) 3832 0.009 0.000 0.013 0.000 sre_parse.py:126(__len__) 3232 0.009 0.000 0.013 0.000 token.py:43(__hash__) 2 0.009 0.004 0.009 0.004 {posix.popen} 688 0.008 0.000 0.186 0.000 sre_compile.py:178(_compile_charset) 934 0.008 0.000 0.801 0.001 re.py:228(_compile) 286 0.008 0.000 0.150 0.001 sre_compile.py:361(_compile_info) 5 0.008 0.002 0.028 0.006 style.py:17(__new__) 1485/27 0.008 0.000 0.011 0.000 nodes.py:189(_fast_traverse) 5253 0.008 0.000 0.008 0.000 {min} 269 0.007 0.000 0.007 0.000 {method 'update' of 'dict' objects} 4114 0.007 0.000 0.011 0.000 {method 'get' of 'dict' objects} 13 0.006 0.000 0.345 0.027 __init__.py:10(<module>) 1 0.006 0.006 0.011 0.011 nodes.py:20(<module>) 1 0.005 0.005 0.494 0.494 application.py:12(<module>) 5 0.005 0.001 0.327 0.065 application.py:351(add_node) 19/18 0.005 0.000 0.289 0.016 {__import__} 1 0.005 0.005 0.227 0.227 states.py:101(<module>) 588 0.005 0.000 0.005 0.000 re.py:206(escape) 2388 0.004 0.000 0.004 0.000 sre_parse.py:90(__init__) 3206 0.004 0.000 0.004 0.000 sre_compile.py:24(_identityfunction) 688 0.004 0.000 0.048 0.000 statemachine.py:690(make_transition) 732 0.004 0.000 0.008 0.000 sre_compile.py:354(_simple) 286 0.004 0.000 0.789 0.003 sre_compile.py:495(compile) 3232 0.004 0.000 0.004 0.000 {hash} 248 0.004 0.000 0.004 0.000 {builtin method __new__ of type object at 0x7fa2a2015f60} 507 0.004 0.000 0.006 0.000 sre_parse.py:225(_class_escape) 288/286 0.003 0.000 0.371 0.001 sre_parse.py:663(parse) 1919 0.003 0.000 0.003 0.000 {marshal.loads} 614 0.003 0.000 0.005 0.000 sre_parse.py:257(_escape) 1841 0.003 0.000 0.003 0.000 {repr} 120 0.003 0.000 0.052 0.000 statemachine.py:723(make_transitions) 917 0.003 0.000 0.792 0.001 re.py:188(compile) 3 0.003 0.001 0.059 0.020 __init__.py:11(<module>) 350 0.003 0.000 0.004 0.000 token.py:15(split) 3 0.003 0.001 0.097 0.032 html.py:10(<module>) 2211 0.003 0.000 0.003 0.000 {method 'extend' of 'list' objects} 1782 0.003 0.000 0.003 0.000 {setattr} 1065 0.002 0.000 0.003 0.000 {hasattr} 861 0.002 0.000 0.002 0.000 pickle.py:1006(load_tuple2) 286 0.002 0.000 0.411 0.001 sre_compile.py:480(_code) 1 0.002 0.002 0.019 0.019 agile.py:10(<module>) 1 0.002 0.002 0.238 0.238 __init__.py:68(<module>) 1040 0.002 0.000 0.002 0.000 {method 'join' of 'str' objects} 345 0.002 0.000 0.003 0.000 pickle.py:933(load_binint2) 1 0.002 0.002 0.310 0.310 latex.py:13(<module>) 572 0.002 0.000 0.003 0.000 sre_compile.py:474(isstring) 1202 0.002 0.000 0.002 0.000 {getattr} 468 0.002 0.000 0.003 0.000 pickle.py:1014(load_empty_list) 4 0.002 0.000 0.002 0.000 {posix.remove} 594 0.002 0.000 0.002 0.000 {range} 233 0.002 0.000 0.004 0.000 pickle.py:1185(load_appends) 203 0.002 0.000 0.003 0.000 other.py:986(_shortened) 1 0.002 0.002 0.168 0.168 environment.py:10(<module>) ... 1 0.000 0.000 0.000 0.000 references.py:7(<module>) 1 0.000 0.000 0.000 0.000 universal.py:13(<module>) 1 0.000 0.000 3.304 3.304 sagedoc.py:333(format) 8 0.000 0.000 0.000 0.000 {_bisect.insort} 70 0.000 0.000 0.000 0.000 __init__.py:41(__init__) ...
So, it seems much time is spent in the function "format". Has there been a change to that function recently? Or am I misinterpreting the figures (I am not sure if "cumtime" and "percall" include the time for calling subfunctions).
comment:3 Changed 11 years ago by
So, it seems much time is spent in the function "format". Has there been a change to that function recently? Or am I misinterpreting the figures (I am not sure if "cumtime" and "percall" include the time for calling subfunctions).
I'm not entirely sure what the output means either. This reminded me that there is some
other information that I should have added, though. gcd?
seems to take a good deal
longer than sage.misc.sageinspect.sage_getdoc(gcd)
, which already takes way too long. (On my machine is it about 2 seconds for the question mark, and about .5 seconds for the direct function call.)
I had thought that most of the time taken by sage.misc.sageinspect.sage_getdoc might be taken up by sage.misc.sagedoc.detex, but that doesn't show up in the above at all, and I don't know what explains the extra 1.5 seconds.
comment:4 Changed 11 years ago by
Could you produce a similar report for sage4.8? If the slow down happened in sage5.0 the most likely candidate would be python itself.
comment:5 followup: 6 Changed 11 years ago by
Here are the various timings:
~» su c 'sync; echo 3 > /proc/sys/vm/drop_caches' Password: ~» Installations/sage4.8.good/sage q sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 0.54 s, sys: 0.06 s, total: 0.60 s Wall time: 3.09 s sage: Exiting Sage (CPU time 0m0.66s, Wall time 0m14.59s). ~» Installations/sage5.0.beta2/sage q Loading Sage library. Current Mercurial branch is: mainbackup sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 0.50 s, sys: 0.05 s, total: 0.56 s Wall time: 1.61 s sage: Exiting Sage (CPU time 0m0.61s, Wall time 0m11.66s). ~» Installations/sage5.0.rc0.good/sage q sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 1.55 s, sys: 0.09 s, total: 1.64 s Wall time: 2.93 s sage: Exiting Sage (CPU time 0m1.67s, Wall time 0m10.45s). ~» Installations/sage5.1beta0/sage q Loading Sage library. Current Mercurial branch is: trac sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 1.06 s, sys: 0.08 s, total: 1.14 s Wall time: 2.03 s sage: Exiting Sage (CPU time 0m1.19s, Wall time 0m10.42s).
comment:6 Changed 11 years ago by
Replying to ppurka:
Here are the various timings:
~» su c 'sync; echo 3 > /proc/sys/vm/drop_caches'
Dropping the caches first is not a good way of timing this. The problem is not with disk access, but something else, so a better test is to get the docstring twice, and use the second timing.
I now think that the change is should be in either 5.0beta7 or 5.0beta8...
comment:7 Changed 11 years ago by
Ok. Here they are again. Haven't dropped caches this time. The sage libraries are already loaded so, the sage q
gives the sage prompt quickly.
~» Installations/sage5.1beta0/sage q Loading Sage library. Current Mercurial branch is: trac sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 1.02 s, sys: 0.05 s, total: 1.07 s Wall time: 1.11 s sage: Exiting Sage (CPU time 0m1.10s, Wall time 0m6.96s). ~» Installations/sage5.0.rc0.good/sage q sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 1.02 s, sys: 0.05 s, total: 1.07 s Wall time: 1.09 s sage: Exiting Sage (CPU time 0m1.10s, Wall time 0m5.61s). ~» Installations/sage5.0.beta2/sage q Loading Sage library. Current Mercurial branch is: mainbackup sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 0.44 s, sys: 0.03 s, total: 0.48 s Wall time: 0.50 s sage: Exiting Sage (CPU time 0m0.52s, Wall time 0m5.43s). ~» Installations/sage4.8.good/sage q sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 0.48 s, sys: 0.04 s, total: 0.52 s Wall time: 0.54 s sage: Exiting Sage (CPU time 0m0.56s, Wall time 0m4.47s).
comment:8 Changed 11 years ago by
So it appears that the regression happened somewhere in 5.0beta8. #9128 seems like it touched a lot of stuff related to this, so it is a possible candidate for the cause of the regression.
(Adding hivert to cc, since he was the author on that ticket.)
comment:9 followup: 11 Changed 11 years ago by
The sphinx ticket. That should be testable starting from beta7 and adding this single ticket.
comment:10 followup: 12 Changed 11 years ago by
There doesn't seem to be much of a difference from sage4.7 (it is a different machine though)
~> ./sage4.7/sage q sage: from sage.misc.sageinspect import sage_getd sage_getdef sage_getdoc sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 0.39 s, sys: 0.09 s, total: 0.48 s Wall time: 0.53 s
This test on sage4.7 is done on a
model name : Intel(R) Xeon(R) CPU X5460 @ 3.16GHz
a virtual machine with 4 cpu cores and with 20G of memory.
The earlier tests were done on my laptop
model name : Intel(R) Core(TM) i5 CPU M 460 @ 2.53GH
with 2 cores (4 with HT) and with 4G of memory.
comment:11 Changed 11 years ago by
comment:12 Changed 11 years ago by
Replying to ppurka:
There doesn't seem to be much of a difference from sage4.7 (it is a different machine though)
~> ./sage4.7/sage q sage: from sage.misc.sageinspect import sage_getd sage_getdef sage_getdoc sage: from sage.misc.sageinspect import sage_getdoc sage: %time L = sage_getdoc(gcd) CPU times: user 0.39 s, sys: 0.09 s, total: 0.48 s Wall time: 0.53 sThis test on sage4.7 is done on a
model name : Intel(R) Xeon(R) CPU X5460 @ 3.16GHza virtual machine with 4 cpu cores and with 20G of memory.
The earlier tests were done on my laptop
model name : Intel(R) Core(TM) i5 CPU M 460 @ 2.53GHwith 2 cores (4 with HT) and with 4G of memory.
Try running the sage_getdoc function a few times in a row with the same input on 4.7 and 5.0 (or just using the question mark) and you should see the difference. You really need to do it a few times in a row, though. The first time may be slow because it is reading from disk (a "warm cache" from starting up sage is not enough to prevent this) but it should not remain slow.
comment:13 Changed 11 years ago by
You are right. There is a slowdown indeed.
~» Installations/sage5.1beta0/sage q Loading Sage library. Current Mercurial branch is: trac sage: from sage.misc.sageinspect import sage_getdoc sage: timeit('L = sage_getdoc(gcd)') 5 loops, best of 3: 624 ms per loop sage: Exiting Sage (CPU time 0m13.41s, Wall time 0m30.68s). ~» Installations/sage5.0.rc0.good/sage q sage: from sage.misc.sageinspect import sage_getdoc sage: timeit('L = sage_getdoc(gcd)') 5 loops, best of 3: 600 ms per loop sage: Exiting Sage (CPU time 0m13.04s, Wall time 0m18.14s). ~» Installations/sage5.0.beta2/sage q Loading Sage library. Current Mercurial branch is: mainbackup sage: from sage.misc.sageinspect import sage_getdoc sage: timeit('L = sage_getdoc(gcd)') 5 loops, best of 3: 18.2 ms per loop sage: Exiting Sage (CPU time 0m0.86s, Wall time 0m5.01s). ~> ./sage4.7/sage q sage: from sage.misc.sageinspect import sage_getdoc sage: timeit('L = sage_getdoc(gcd)') 5 loops, best of 3: 17.8 ms per loop
comment:14 Changed 11 years ago by
Just tested on sage5.0beta7. The patch responsible for the slowdown is the second one from that ticket: http://trac.sagemath.org/sage_trac/attachment/ticket/9128/trac_9128sphinx_links_allfh.patch
comment:15 Changed 11 years ago by
Perhaps it's the intersphinx invocation? Maybe we should disable that during introspection, and maybe the same for the dangling links. Something like this?

doc/common/conf.py
diff git a/doc/common/conf.py b/doc/common/conf.py
a b def setup(app): 608 608 app.connect('autodocprocessdocstring', process_inherited) 609 609 app.connect('autodocskipmember', skip_member) 610 610 611 app.add_config_value('intersphinx_mapping', {}, True) 612 app.add_config_value('intersphinx_cache_limit', 5, False) 613 # We do *not* fully initialize intersphinx since we call it by hand 614 # in find_sage_dangling_links. 615 # app.connect('missingreference', missing_reference) 616 app.connect('missingreference', find_sage_dangling_links) 617 import sphinx.ext.intersphinx 618 app.connect('builderinited', set_intersphinx_mappings) 619 app.connect('builderinited', sphinx.ext.intersphinx.load_mappings) 611 # When building the standard docs, app.srcdir is set to SAGE_DOC + 612 # 'LANGUAGE/DOCNAME', but when doing introspection, app.srcdir is 613 # set to a temporary directory. We don't want to use intersphinx, 614 # etc., when doing introspection. 615 if app.srcdir.startswith(SAGE_DOC): 616 app.add_config_value('intersphinx_mapping', {}, True) 617 app.add_config_value('intersphinx_cache_limit', 5, False) 618 # We do *not* fully initialize intersphinx since we call it by hand 619 # in find_sage_dangling_links. 620 # app.connect('missingreference', missing_reference) 621 app.connect('missingreference', find_sage_dangling_links) 622 import sphinx.ext.intersphinx 623 app.connect('builderinited', set_intersphinx_mappings) 624 app.connect('builderinited', sphinx.ext.intersphinx.load_mappings) 620 625 app.connect('builderinited', nitpick_patch_config)
comment:16 Changed 11 years ago by
For me, without this change:
sage: from sage.misc.sageinspect import sage_getdoc sage: timeit('L = sage_getdoc(gcd)') 5 loops, best of 3: 888 ms per loop
With the change:
sage: from sage.misc.sageinspect import sage_getdoc sage: timeit('L = sage_getdoc(gcd)') 5 loops, best of 3: 26 ms per loop
Changed 11 years ago by
Attachment:  trac_13057nointersphinx.patch added 

comment:17 Changed 11 years ago by
Authors:  → John Palmieri 

Cc:  Florent Hivert added 
Status:  new → needs_review 
Here is essentially the above patch (although I've now also included the last line in the "if" block). Please test it from the command line and in the notebook, and you should probably also build the regular documentation and make sure it still looks okay.
When I was testing this, I added a line to try to verify that app.srcdir is as I'm claiming in the patch (this applies on top of the attached patch):

doc/common/conf.py
diff git a/doc/common/conf.py b/doc/common/conf.py
a b def setup(app): 608 608 app.connect('autodocprocessdocstring', process_inherited) 609 609 app.connect('autodocskipmember', skip_member) 610 610 611 print "************* %s **************" % app.srcdir 612 611 613 # When building the standard docs, app.srcdir is set to SAGE_DOC + 612 614 # 'LANGUAGE/DOCNAME', but when doing introspection, app.srcdir is 613 615 # set to a temporary directory. We don't want to use intersphinx,
Florent: is this a good solution (i.e., not using intersphinx, etc., when doing introspection)?
comment:18 followup: 19 Changed 11 years ago by
Summary:  introspection is slow → introspection is slow and causes a significant memory leak 

As I just reported on sagedevel, #9128 apparently also introduced a pretty large memory leak  every docstring lookup with "?" in the console leaks 56 MB of memory. This patch fixes the leak.
comment:19 Changed 11 years ago by
This patch seems to take care of my complaints nicely. I don't know what is actually going on with it, though, so I hope that someone who does know will give it a review.
The 56 MB memory leak is worrying, though, and we should figure out why that was happening. Does someone know?
comment:20 followup: 21 Changed 10 years ago by
Should this ticket be priority critical? Users use introspection a lot, in my experience. This is not just some obscure memory leak.
comment:21 Changed 10 years ago by
Replying to kini:
Should this ticket be priority critical? Users use introspection a lot, in my experience. This is not just some obscure memory leak.
If this also solves the fact that building the doc now uses a HUGE amount of memory, I'd vote for this ticket being critical.
comment:22 Changed 10 years ago by
Nevermind, the doc building problem is already present in 4.8 so is completely unrelated, I mixed two different threads on sagedevel. Sorry for the noise.
comment:23 Changed 10 years ago by
This is related to docbuilding using a lot of memory, but it doesn't solve that problem. It suggests that the problem comes from using intersphinx, and this might help someone track down the exact issue. Is there a ticket open for this issue?
comment:24 Changed 10 years ago by
Priority:  major → critical 

I agree with Keshav: this ticket should have a higher priority. Any possible reviewers?
comment:25 followup: 26 Changed 10 years ago by
I can confirm that this patch works, and fixes all the issues raised here. But I know nothing about sphinx, so I am not sure about setting it to positive review.
comment:26 Changed 10 years ago by
Replying to ppurka:
I can confirm that this patch works, and fixes all the issues raised here. But I know nothing about sphinx, so I am not sure about setting it to positive review.
I wan't to have a close look at this one (understanding why there is a such a huge slowdown/memleak). It seems that the intersphinx database is recreated at each run (which is very bad wrt speed, caching the result should be doable) and not garbage collected (which is even worse). But I can't manage to find the time to do it. I is clearly critical or blocker. I'm soory, I didn't find the time to even apply the patch. Does it deactivate intersphinx when using ??
*in the notebook* ? If so, I think we should look for a better solution because not calling find_sage_dangling_links
breaks hundreds of links (see #9128).
Sorry that my machine is very fast and that I didn't notice the problem when writing #9128.
Cheers,
Florent
comment:27 Changed 10 years ago by
Before applying the patch, executing sage.algebras.group_algebra_new.GroupAlgebra.one_basis?
(or the same but with ??
) in the notebook displays something which looks like a link, but is broken, at least for me running Chrome or Firefox on OS X 10.7. The link is of the form
localhost:8000/FULL_PATH_TO_REFERENCE_MANUAL/sage/categories/algebras_with_basis.html#sage.categories.algebras_with_basis.AlgebrasWithBasis.ParentMethods.one_basis
It should probably be of the form
localhost:8000/doc/static/reference/sage/categories/...
That is, the desired behavior is currently broken.
After applying the patch, there is no link at all.
So I would propose that we use this fix for now, since it speeds things up, prevents a memory leak, and doesn't disable anything which currently works. Then later when you have time, we can work on tracking down the memory leak, reinstating intersphinx in the notebook, and fixing the links so that they actually work. (Just fixing the link is, I think, currently unacceptable given the slowdown and the memory leak issues.)
comment:28 Changed 10 years ago by
Reviewers:  → Keshav Kini 

Status:  needs_review → positive_review 
The leak is ridiculously bad. I'm going to give this positive review  whatever else this patch might do, it does fix that, at least.
comment:29 Changed 10 years ago by
comment:30 Changed 10 years ago by
Merged in:  → sage5.1.beta5 

Resolution:  → fixed 
Status:  positive_review → closed 
As another point of reference: If I run
sage ipython
and then trystr?
, I get the docstring immediately. If I then dofrom sage.all import *
the same thing now takes a second or two.